Postgrest: 500 Error with node

[isairz]

In safari, chrome and postman works ok, but node http client works fail.

MacOS Sierra 10.12
PostgREST 0.3.2.0
node v6.9.1

postgrest postgres://localhost:5432/mydb -a myaccount -m 12

// Request: 'GET / HTTP/1.1\r\nHost: localhost:3000\r\nConnection: close\r\n\r\n'
// Response: 'Something went wrongHTTP/1.0 500 Internal Server Error\r\nDate: Sun, 23 Oct 2016 05:17:37 GMT\r\nServer: postgrest/0.3.2.0\r\nContent-Type: text/plain; charset=utf-8\r\n\r\nSomething went wrong'

http.get('http://localhost:3000/', res=> console.log(res.statusCode))

fetch = require('isomorphic-fetch')
fetch('http://localhost:3000/').then(res => console.log(res.status)).catch(err => console.log(err))

postgrest = require('postgrest-request')
postgrest('http://localhost:3000').get('/').end((err,data) => console.log(data))

request = require('request')
request('http://localhost:3000/', (err, res, body) => console.log(body))

[ruslantalpa]

Paste the following things:

• db schema that generates this error
• the output in the console where postgrest is running (don't start it in the background) if any
• the raw network http request/response (not just the js code)

[ruslantalpa]

also make sure the db is up and running before you start postgrest (it was the problem here https://github.com/begriffs/postgrest/issues/682)

[isairz]

• PostgreSQL is running as service
• PostgREST is running in zsh (started after PostgreSQL running)
• '/' and '/pages' has same issue.
• curl http://localhost:3000/pages works fine
  
  
  
  • ::1 - - [23/Oct/2016:14:54:57 +0900] "GET /pages HTTP/1.1" 206 - "" "curl/7.49.1"
  
  

table schema for pages

                                                       Table "public.pages"
  Column   |           Type           |                     Modifiers                      | Storage  | Stats target | Description
-----------+--------------------------+----------------------------------------------------+----------+--------------+-------------
 id        | integer                  | not null default nextval('pages_id_seq'::regclass) | plain    |              |
 index     | integer                  |                                                    | plain    |              |
 name      | character varying(255)   | not null                                           | extended |              |
 width     | integer                  |                                                    | plain    |              |
 height    | integer                  |                                                    | plain    |              |
 createdAt | timestamp with time zone | not null                                           | plain    |              |
 updatedAt | timestamp with time zone | not null                                           | plain    |              |
 postId    | integer                  |                                                    | plain    |              |

Raw Request

GET /pages HTTP/1.1\r\nHost: localhost:3000\r\nConnection: close\r\n\r\n

Raw Response (with no postgrest log)

HTTP/1.0 500 Internal Server Error
Date: Sun, 23 Oct 2016 05:52:33 GMT
Server: postgrest/0.3.2.0
Content-Type: text/plain; charset=utf-8

Something went wrongHTTP/1.0 500 Internal Server Error
Date: Sun, 23 Oct 2016 05:52:33 GMT
Server: postgrest/0.3.2.0
Content-Type: text/plain; charset=utf-8

Something went wrong

[isairz]

Ooops! After reboot my mac, It works fine.

I restarted PostgREST several times before reboot, but it didn't work.
I do not know what the problem was, sorry.

[begriffs]

Hm, do you have access to the PostgreSQL logs from the previous runs? I'd like to reproduce the problem if I can.

[isairz]

Raw Log ( I installed postgreSQL by homebrew. )

"root" execution of the PostgreSQL server is not permitted.
The server must be started under an unprivileged user ID to prevent
possible system security compromise.  See the documentation for
more information on how to properly start the server.
"root" execution of the PostgreSQL server is not permitted.
The server must be started under an unprivileged user ID to prevent
possible system security compromise.  See the documentation for
more information on how to properly start the server.
LOG:  received smart shutdown request    <<<<<<< REBOOT
LOG:  autovacuum launcher shutting down
LOG:  shutting down
LOG:  database system is shut down
"root" execution of the PostgreSQL server is not permitted.
The server must be started under an unprivileged user ID to prevent
possible system security compromise.  See the documentation for
more information on how to properly start the server.
LOG:  database system was shut down at 2016-10-23 15:20:14 KST
LOG:  MultiXact member wraparound protections are now enabled
LOG:  autovacuum launcher started
LOG:  database system is ready to accept connections
"root" execution of the PostgreSQL server is not permitted.
The server must be started under an unprivileged user ID to prevent
possible system security compromise.  See the documentation for
more information on how to properly start the server.

Permission Error removed

ERROR:  syntax error at or near "select" at character 22
STATEMENT:  select count(*) from select distinct unnest(tags) from posts;^@
ERROR:  syntax error at or near "count" at character 1
STATEMENT:  count(select distinct unnest(tags) from posts);^@
ERROR:  subquery in FROM must have an alias at character 22
HINT:  For example, FROM (SELECT ...) [AS] foo.
STATEMENT:  select count(*) from (select distinct unnest(tags) from posts);^@
ERROR:  relation "public.favicon.ico" does not exist at character 66
STATEMENT:
        WITH pg_source AS (SELECT  "public"."favicon.ico".* FROM  "public"."favicon.ico"    LIMIT 12 OFFSET 0) SELECT (SELECT pg_catalog.count(1) FROM  "public"."favicon.ico" ) AS total_result_set, pg_catalog.count(t) AS page_total, array[]::text[] AS header, coalesce(array_to_json(array_agg(row_to_json(t))), '[]')::character varying AS body
        FROM ( SELECT * FROM pg_source) t ^@
  from information_schema.schemata^@
LOG:  received smart shutdown request    <<<<<<< REBOOT
LOG:  autovacuum launcher shutting down
LOG:  shutting down
LOG:  database system is shut down^@
LOG:  database system was shut down at 2016-10-23 15:20:14 KST
LOG:  MultiXact member wraparound protections are now enabled
LOG:  autovacuum launcher started
LOG:  database system is ready to accept connections^@
ERROR:  relation "public.favicon.ico" does not exist at character 66

[tnhu]

I confirm it happened to me too. After restarting my mac, the issue goes away. It's super weird that it worked with curl, browsers, and postman but not under nodejs (tested with axios and isomorphic-fetch).

Probably a nodejs issue?

[begriffs]

Can you spy on the HTTP traffic for me and see if there is any difference in the requests? Try the ngrep instructions in the new docs - https://postgrest.readthedocs.io/en/v0.4/admin.html#debugging

[tnhu]

@begriffs I could not reproduce the issue after restarting my mac. Will post the HTTP traffic if I encounter the issue again.

[begriffs]

I'd still be curious to see if there is any difference in the HTTP requests in node vs curl. Even if you can't reproduce the problem right now, the traffic dump can help us get a head-start thinking about the cause.

[tnhu]

Make sense. Here you go:

create table foobar(msg text);
insert into foobar values('Hello');
insert into foobar values('World');

curl -v http://localhost:3333/foobar

*   Trying ::1...
* connect to ::1 port 3333 failed: Connection refused
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 3333 (#0)
> GET /foobar HTTP/1.1
> Host: localhost:3333
> User-Agent: curl/7.43.0
> Accept: */*
>
< HTTP/1.1 200 OK
< Transfer-Encoding: chunked
< Date: Fri, 30 Dec 2016 00:34:54 GMT
< Server: postgrest/0.3.2.0
< Content-Type: application/json; charset=utf-8
< Content-Range: 0-1/*
< Content-Location: /foobar
<
* Connection #0 to host localhost left intact
[{"msg":"Hello"},{"msg":"World"}]


#############
T 127.0.0.1:51181 -> 127.0.0.1:3333 [AP]
  GET /foobar HTTP/1.1..Host: localhost:3333..User-Agent:
   curl/7.43.0..Accept: */*....
##
T 127.0.0.1:3333 -> 127.0.0.1:51181 [AP]
  HTTP/1.1 200 OK..Transfer-Encoding: chunked..Date: Fri,
   30 Dec 2016 00:46:33 GMT..Server: postgrest/0.3.2.0..C
  ontent-Type: application/json; charset=utf-8..Content-R
  ange: 0-1/*..Content-Location: /foobar....0021..[{"msg"
  :"Hello"},{"msg":"World"}]..0....
######

require('axios').get('http://localhost:3333/foobar').then(res => console.log(res))

Promise { <pending> }
> { status: 200,
  statusText: 'OK',
  headers:
   { 'transfer-encoding': 'chunked',
     date: 'Fri, 30 Dec 2016 00:40:31 GMT',
     server: 'postgrest/0.3.2.0',
     'content-type': 'application/json; charset=utf-8',
     'content-range': '0-1/*',
     'content-location': '/foobar' },
  config:
   { adapter: [Function: httpAdapter],
     transformRequest: { '0': [Function: transformRequest] },
     transformResponse: { '0': [Function: transformResponse] },
     timeout: 0,
     xsrfCookieName: 'XSRF-TOKEN',
     xsrfHeaderName: 'X-XSRF-TOKEN',
     maxContentLength: -1,
     validateStatus: [Function: validateStatus],
     headers:
      { Accept: 'application/json, text/plain, */*',
        'User-Agent': 'axios/0.15.3' },
     method: 'get',
     url: 'http://localhost:3333/foobar',
     data: undefined },
  request:
   Writable {
     _writableState:
      WritableState {
        objectMode: false,
        highWaterMark: 16384,
        needDrain: false,
        ending: false,
        ended: false,
        finished: false,
        decodeStrings: true,
        defaultEncoding: 'utf8',
        length: 0,
        writing: false,
        corked: 0,
        sync: true,
        bufferProcessing: false,
        onwrite: [Function],
        writecb: null,
        writelen: 0,
        bufferedRequest: null,
        lastBufferedRequest: null,
        pendingcb: 0,
        prefinished: false,
        errorEmitted: false,
        bufferedRequestCount: 0,
        corkedRequestsFree: [Object] },
     writable: true,
     domain: null,
     _events:
      { response: [Function: handleResponse],
        error: [Function: handleRequestError] },
     _eventsCount: 2,
     _maxListeners: undefined,
     _options:
      { maxRedirects: 21,
        protocol: 'http:',
        hostname: 'localhost',
        port: '3333',
        path: '/foobar',
        method: 'get',
        headers: [Object],
        agent: undefined,
        auth: undefined },
     _redirectCount: 0,
     _onNativeResponse: [Function],
     _currentRequest:
      ClientRequest {
        domain: null,
        _events: [Object],
        _eventsCount: 3,
        _maxListeners: undefined,
        output: [],
        outputEncodings: [],
        outputCallbacks: [],
        outputSize: 0,
        writable: true,
        _last: true,
        chunkedEncoding: false,
        shouldKeepAlive: false,
        useChunkedEncodingByDefault: false,
        sendDate: false,
        _removedHeader: {},
        _contentLength: 0,
        _hasBody: true,
        _trailer: '',
        finished: true,
        _headerSent: true,
        socket: [Object],
        connection: [Object],
        _header: 'GET /foobar HTTP/1.1\r\nAccept: application/json, text/plain, */*\r\nUser-Agent: axios/0.15.3\r\nHost: localhost:3333\r\nConnection: close\r\n\r\n',
        _headers: [Object],
        _headerNames: [Object],
        _onPendingData: null,
        agent: [Object],
        socketPath: undefined,
        method: 'GET',
        path: '/foobar',
        _redirectable: [Circular],
        parser: null,
        res: [Object] },
     _currentUrl: 'http://localhost:3333' },
  data: [ { msg: 'Hello' }, { msg: 'World' } ] }

#############
T 127.0.0.1:51169 -> 127.0.0.1:3333 [AP]
  GET /foobar HTTP/1.1..Accept: application/json, text/pl
  ain, */*..User-Agent: axios/0.15.3..Host: localhost:333
  3..Connection: close....
##
T 127.0.0.1:3333 -> 127.0.0.1:51169 [AP]
  HTTP/1.1 200 OK..Transfer-Encoding: chunked..Date: Fri,
   30 Dec 2016 00:46:11 GMT..Server: postgrest/0.3.2.0..C
  ontent-Type: application/json; charset=utf-8..Content-R
  ange: 0-1/*..Content-Location: /foobar....0021..[{"msg"
  :"Hello"},{"msg":"World"}]..0....
######

response-axios.txt
response-curl.txt

[begriffs]

Well I'm closing this issue for now. If it happens again then at least we have a place to begin debugging.

[DouglasSanders]

I recently had this same issue occur (on PostgREST 0.4.0.0) - and the issue also resolved itself after a restart.

I've captured the ngrep logs as you requested above in case they help.

With curl:

#####
T ::1:63871 -> ::1:4100 [AP]
  GET /daily_client_summary HTTP/1.1..Host: localhost:4100..User-Agent: curl/7.51.0..Accept: */*....
##
T ::1:4100 -> ::1:63871 [AP]
  HTTP/1.1 200 OK..Transfer-Encoding: chunked..Date: Mon, 13 Mar 2017 10:35:20 GMT..Server: postgrest/0.4.0.0..Content-Type: application/json; charset=utf-8..Content-Range: 0-99/*..Content-Location: /daily_client_summary....1CA6..[{response_data}]..0....
#####

When throwing HTTP 500 (Here using a hackney client):

##########
T 127.0.0.1:63917 -> 127.0.0.1:4100 [AP]
  GET /daily_client_summary HTTP/1.1..User-Agent: hackney/1.6.6..Host: localhost:4100....
##
T 127.0.0.1:4100 -> 127.0.0.1:63917 [AP]
  HTTP/1.0 500 Internal Server Error..Date: Mon, 13 Mar 2017 10:36:53 GMT..Server: postgrest/0.4.0.0..Content-Type: text/plain; charset=utf-8....Something went wrong
##
T 127.0.0.1:4100 -> 127.0.0.1:63917 [AP]
  HTTP/1.0 500 Internal Server Error..Date: Mon, 13 Mar 2017 10:36:53 GMT..Server: postgrest/0.4.0.0..Content-Type: text/plain; charset=utf-8....Something went wrong
###

When working as expected (after restart):

#
T 127.0.0.1:49659 -> 127.0.0.1:4100 [AP]
  GET /daily_client_summary HTTP/1.1..User-Agent: hackney/1.6.6..Host: localhost:4100....                                 
##
T 127.0.0.1:4100 -> 127.0.0.1:49659 [AP]
  HTTP/1.1 200 OK..Transfer-Encoding: chunked..Date: Mon, 13 Mar 2017 10:43:37 GMT..Server: postgrest/0.4.0.0..Content-Type: application/json; charset=utf-8..Content-Range: 0-99/*..Content-Location: /daily_client_summary....1CA6..[{response_data}]..0....    

[begriffs]

@DouglasSanders do you have db sql logs for the time when the server had an error?

[DouglasSanders]

Unfortunately I do not. If the issue reoccurs, I will be sure to capture the logs.

[DouglasSanders]

@begriffs I've had the issue reoccur and captured the logs as requested. I'll note that the SQL runs as expected (produces the output I expect in the result body) if I execute it directly, and that the queries run are identical when postgrest is working as expected.

ngrep log:

interface: lo0 (127.0.0.0/255.0.0.0)
filter: (ip or ip6) and ( port 4100 )
#####
T 127.0.0.1:63608 -> 127.0.0.1:4100 [AP]
  GET /mv_sales_summary_r12m_p12m HTTP/1.1..Authorization: Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJVc2Vy
  OmMyM2ExNTU4LWUwYWItNDk4Ni1iODBlLWY4NzViODFiMDdmYSIsImV4cCI6MTQ5MjA1ODIwNSwiaWF0IjoxNDkxNzk5MDA1LCJpc3MiOiJrb2ppa2kuY
  mxhY2t0YW5nZW50LmlvIiwianRpIjoiNmNkZWZlYWUtNWQ3Yi00N2RlLWFjZTEtYzM4MzVkYWM2MWZhIiwicGVtIjp7fSwicm9sZSI6InJlYWRlciIsIn
  N1YiI6IlVzZXI6YzIzYTE1NTgtZTBhYi00OTg2LWI4MGUtZjg3NWI4MWIwN2ZhIiwidHlwIjoiYWNjZXNzIn0.jTY4c3hxgG3ten9bZad-W0fwRw1mC_R
  BfEgXseK6MZc..User-Agent: hackney/1.6.6..Host: localhost:4100....                                                    
##
T 127.0.0.1:4100 -> 127.0.0.1:63608 [AP]
  HTTP/1.0 500 Internal Server Error..Date: Mon, 10 Apr 2017 04:36:45 GMT..Server: postgrest/0.4.0.0..Content-Type: tex
  t/plain; charset=utf-8....Something went wrong                                                                       
##
T 127.0.0.1:4100 -> 127.0.0.1:63608 [AP]
  HTTP/1.0 500 Internal Server Error..Date: Mon, 10 Apr 2017 04:36:45 GMT..Server: postgrest/0.4.0.0..Content-Type: tex
  t/plain; charset=utf-8....Something went wrong                                                                       
#####

and the postgres log:

LOG:  connection received: host=::1 port=63508
LOG:  connection authorized: user=authenticator database=track_development
LOG:  statement: SET client_encoding = 'UTF8';SET client_min_messages TO WARNING;
LOG:  execute 0: BEGIN ISOLATION LEVEL READ COMMITTED READ ONLY
LOG:  statement: set local role 'reader';set local "request.jwt.claim.sub" = 'User:c23a1558-e0ab-4986-b80e-f875b81b07fa';set local "request.jwt.claim.jti" = 'c9152fc9-4650-468e-a2d5-602a477a0929';set local "request.jwt.claim.exp" = '1492057966';set local "request.jwt.claim.pem" = '{}';set local "request.jwt.claim.iss" = 'kojiki.blacktangent.io';set local "request.jwt.claim.iat" = '1491798766';set local "request.jwt.claim.typ" = 'access';set local "request.jwt.claim.aud" = 'User:c23a1558-e0ab-4986-b80e-f875b81b07fa';
LOG:  execute <unnamed>: 
          WITH pg_source AS (SELECT  "live"."mv_sales_summary_r12m_p12m".* FROM  "live"."mv_sales_summary_r12m_p12m"    LIMIT 1000 OFFSET 0) SELECT null AS total_result_set, pg_catalog.count(_postgrest_t) AS page_total, array[]::text[] AS header, coalesce(array_to_json(array_agg(row_to_json(_postgrest_t))), '[]')::character varying AS body
          FROM ( SELECT * FROM pg_source) _postgrest_t 
LOG:  execute 1: COMMIT

[chesles]

I'm seeing this on 0.4.1.0 on OSX 10.11.6. The only obvious difference between node and curl requests is header capitalization, which shouldn't make a difference. The SQL is identical in both as has been mentioned.

Strangely, with the node client postgrest doesn't log the request to stdout, but both ngrep and node output show two copies of the error response from postgrest. The second copy of the status code and headers gets interpreted as part of the body. Node versions 4.3.0, 6.9.2, and 8.0.0 all behave the same.

Here are all my logs (click to expand):

curl (expected results)

• curl -v

$ curl -v localhost:4000/app_subscriptions
*   Trying ::1...
* Connected to localhost (::1) port 4000 (#0)
> GET /app_subscriptions HTTP/1.1
> Host: localhost:4000
> User-Agent: curl/7.43.0
> Accept: */*
>
< HTTP/1.1 200 OK
< Transfer-Encoding: chunked
< Date: Tue, 06 Jun 2017 14:05:21 GMT
< Server: postgrest/0.4.1.0
< Content-Type: application/json; charset=utf-8
< Content-Range: 0-3/*
< Content-Location: /app_subscriptions
<
* Connection #0 to host localhost left intact
[ (my data) ]

• ngrep:

#####
T ::1:59453 -> ::1:4000 [AP]
  GET /app_subscriptions HTTP/1.1..Host: localhost:4000..User-Agent: curl/7.43.0..Acce
  pt: */*....
##
T ::1:4000 -> ::1:59453 [AP]
  HTTP/1.1 200 OK..Transfer-Encoding: chunked..Date: Tue, 06 Jun 2017 14:05:21 GMT..Se
  rver: postgrest/0.4.1.0..Content-Type: application/json; charset=utf-8..Content-Rang
  e: 0-3/*..Content-Location: /app_subscriptions....059C..[ (my data) ]..0....

• postgres log:

LOG:  statement: SET client_encoding = 'UTF8';SET client_min_messages TO WARNING;
LOG:  execute 0: BEGIN ISOLATION LEVEL READ COMMITTED READ ONLY
LOG:  statement: set local role 'postgres';set local "request.jwt.claim.role" = 'postgres';set local "request.header.host" = 'localhost:4000';set local "request.header.user-agent" = 'curl/7.43.0';set local "request.header.accept" = '*/*';
LOG:  execute <unnamed>:
          WITH pg_source AS (SELECT  "api"."app_subscriptions".* FROM  "api"."app_subscriptions"    ) SELECT null AS total_result_set, pg_catalog.count(_postgrest_t) AS page_total, array[]::text[] AS header, coalesce(array_to_json(array_agg(row_to_json(_postgrest_t))), '[]')::character varying AS body
          FROM ( SELECT * FROM pg_source) _postgrest_t
LOG:  execute 1: COMMIT

• postgrest log

::1 - - [06/Jun/2017:10:05:21 -0400] "GET /app_subscriptions HTTP/1.1" 200 - "" "curl/7.43.0"

node (error)

• node script

const request = require('request')
const url = 'http://localhost:4000/app_subscriptions'

request.get(url, log)

function log (err, res, body) {
  if (err) console.error(err)
  else console.log(res.headers, body)
}

• node output

{ date: 'Tue, 06 Jun 2017 14:17:05 GMT',
  server: 'postgrest/0.4.1.0',
  'content-type': 'text/plain; charset=utf-8' } 'Something went wrongHTTP/1.0 500 Internal Server Error\r\nDate: Tue, 06 Jun 2017 14:17:05 GMT\r\nServer: postgrest/0.4.1.0\r\nContent-Type: text/plain; charset=utf-8\r\n\r\nSomething went wrong'

• ngrep

#####
T 127.0.0.1:59473 -> 127.0.0.1:4000 [AP]
  GET /app_subscriptions HTTP/1.1..host: localhost:4000..Connection: close....
##
T 127.0.0.1:4000 -> 127.0.0.1:59473 [AP]
  HTTP/1.0 500 Internal Server Error..Date: Tue, 06 Jun 2017 14:17:05 GMT..Server: pos
  tgrest/0.4.1.0..Content-Type: text/plain; charset=utf-8....Something went wrong
##
T 127.0.0.1:4000 -> 127.0.0.1:59473 [AP]
  HTTP/1.0 500 Internal Server Error..Date: Tue, 06 Jun 2017 14:17:05 GMT..Server: pos
  tgrest/0.4.1.0..Content-Type: text/plain; charset=utf-8....Something went wrong
########

• postgres logs

LOG:  statement: SET client_encoding = 'UTF8';SET client_min_messages TO WARNING;
LOG:  execute 0: BEGIN ISOLATION LEVEL READ COMMITTED READ ONLY
LOG:  statement: set local role 'postgres';set local "request.jwt.claim.role" = 'postgres';set local "request.header.host" = 'localhost:4000';set local "request.header.connection" = 'close';
LOG:  execute <unnamed>:
          WITH pg_source AS (SELECT  "api"."app_subscriptions".* FROM  "api"."app_subscriptions"    ) SELECT null AS total_result_set, pg_catalog.count(_postgrest_t) AS page_total, array[]::text[] AS header, coalesce(array_to_json(array_agg(row_to_json(_postgrest_t))), '[]')::character varying AS body
          FROM ( SELECT * FROM pg_source) _postgrest_t
LOG:  execute 1: COMMIT

Update to add ngrep inspecting postgres; looks like postgrest is getting data from the query and errors out sometime afterwards before sending it back to the client:

ngrep port 5432

• sudo ngrep -d lo0 port 5432

interface: lo0 (127.0.0.0/255.0.0.0)
filter: (ip or ip6) and ( port 5432 )
#####
T ::1:61069 -> ::1:5432 [AP]
  ......./
##
T ::1:5432 -> ::1:61069 [AP]
  N
##
T ::1:61069 -> ::1:5432 [AP]
  ...-....user.jchesley.database.intel_db_dev..
##
T ::1:5432 -> ::1:61069 [AP]
  R........S....application_name..S....client_encoding.UTF8.S....DateStyle.ISO, MDY.S.
  ...integer_datetimes.on.S....IntervalStyle.postgres.S....is_superuser.on.S....server
  _encoding.UTF8.S....server_version.9.6.1.S...#session_authorization.jchesley.S...#st
  andard_conforming_strings.on.S....TimeZone.US/Eastern.K......vi,...Z....I
##
T ::1:61069 -> ::1:5432 [AP]
  Q...ESET client_encoding = 'UTF8';SET client_min_messages TO WARNING;.
##
T ::1:5432 -> ::1:61069 [AP]
  S....client_encoding.UTF8.C....SET.C....SET.Z....I
##
T ::1:61069 -> ::1:5432 [AP]
  P...70.BEGIN ISOLATION LEVEL READ COMMITTED READ ONLY...S....
##
T ::1:5432 -> ::1:61069 [AP]
  1....Z....I
##
T ::1:61069 -> ::1:5432 [AP]
  B.....0.........D....P.E.........S....
##
T ::1:5432 -> ::1:61069 [AP]
  2....n....C....BEGIN.Z....T
##
T ::1:61069 -> ::1:5432 [AP]
  Q....set local role 'postgres';set local "request.jwt.claim.role" = 'postgres';set l
  ocal "request.header.host" = 'localhost:4000';set local "request.header.connection"
  = 'close';.
##
T ::1:5432 -> ::1:61069 [AP]
  S....is_superuser.on.C....SET.C....SET.C....SET.C....SET.Z....T
##
T ::1:61069 -> ::1:5432 [AP]
  P...g..      WITH pg_source AS (SELECT  "api"."app_subscriptions".* FROM  "api"."app
  _subscriptions"    ) SELECT null AS total_result_set, pg_catalog.count(_postgrest_t)
   AS page_total, array[]::text[] AS header, coalesce(array_to_json(array_agg(row_to_j
  son(_postgrest_t))), '[]')::character varying AS body.      FROM ( SELECT * FROM pg_
  source) _postgrest_t ...B..............D....P.E.........S....
##
T ::1:5432 -> ::1:61069 [AP]
  1....2....T...v..total_result_set...................page_total...................hea
  der...................body...................D......................................
  ....[ (my data) ]C....SELECT 1.Z....T
##
T ::1:61069 -> ::1:5432 [AP]
  P....1.COMMIT...S....
##
T ::1:5432 -> ::1:61069 [AP]
  1....Z....T
##
T ::1:61069 -> ::1:5432 [AP]
  B.....1.........D....P.E.........S....
##
T ::1:5432 -> ::1:61069 [AP]
  2....n....S....is_superuser.on.C....COMMIT.Z....I
##
T ::1:61069 -> ::1:5432 [AP]
  X....
########

[begriffs]

First of all, wow cool use of <details> and <summary> in a comment! I'm going to copy you when my comments include long sections of output.

Next, thanks for the very thorough report. It does appear that postgrest is having trouble somewhere in between the request and response. I pushed a branch detailed-errors to github that replaces the generic "Something went wrong" with an actual description of the exception. Could you build from that branch and try your test again please?

[chesles]

@begriffs things are working for me right now after rebooting, but I have that branch built and will update here again if/when I start seeing this error again. Thanks!

[lgfausak]

i just had this issue occur. reading here i see that it could be caused by postgrest starting before the database. i did a kill -1 on the postgrest process and it started working. i am pretty sure this is the issue, i am running a postgres container, and a postgrest container. sometimes the postgrest start faster than postgres. not sure what to do about that. i am using the begriffs postgrest image. I guess i could wrap it and put a sleep in there?

[begriffs]

@lgfausak which version of postgrest are you using? The latest version should detect that the db is not yet started and retry the connection with exponential backoff.

[chesles]

Started seeing this again today, and I noticed I actually had 2 postgrest processes running. It seems to happen when the parent process exits (e.g. terminal window is closed) and postgrest doesn't exit cleanly. Here is the output from the detailed-errors branch:

{ date: 'Wed, 18 Oct 2017 20:54:58 GMT',
  server: 'postgrest/0.4.1.0',
  'content-type': 'application/json; charset=utf-8' } '{"message":"<stdout>: hPutBuf: hardware fault (Input/output error)"}HTTP/1.0 500 Internal Server Error\r\nDate: Wed, 18 Oct 2017 20:54:58 GMT\r\nServer: postgrest/0.4.1.0\r\nContent-Type: application/json; charset=utf-8\r\n\r\n{"message":"<stderr>: hPutChar: hardware fault (Input/output error)"}'

Steps to reproduce on OSX:

1. start postgrest in a terminal window
2. close that terminal
3. start a new postgrest process in a new shell
4. run curl 127.0.0.1:4000/some_table

For reasons that aren't clear to me, the old postgrest is still listening on ipv4 localhost, 127.0.0.1:4000, which is what node tries first. When the new process starts, it listens successfully on ipv6 localhost ::1:4000, which is what curl tries first. Any request to the old process throws an error when that process tries to write to stdout.

[steve-chavez]

Thanks to @chesles report, I think I understand why this happens.

First, the default server-host="*4"(any IPv4 or IPv6 hostname, IPv4 preferred) is used and as mentioned in warp docs:
Note that the permissive * values allow binding to an IPv4 or an IPv6 hostname, which means you might be able to successfully bind to a port more times than you expect (eg once on the IPv4 localhost 127.0.0.1 and again on the IPv6 localhost 0:0:0:0:0:0:0:1)

Second, one pgrst process is started and it binds to an ipv4 address, then the terminal window is closed and this sends a SIGHUP, since pgrst uses this signal for reloading it's schema cache, it doesn't quit and prints reloading messages to stdout(broken), that's why the 500 error is shown.

Third and lastly, a second pgrst process is started and then it's bound to ::1(some of the reported logs show this), and as reported Node will fail since it tries ipv4 first whereas curl(unless forced with --ipv4) and browser/postman requests will succeed since they try ipv6 first(will also fail in the same way after closing it's terminal window).

Note: I can't reproduce this *4 behavior on Linux, after closing the terminal window and trying to start a new pgrst process I get an Address already in use error. That's because on Linux, when net.ipv6.bindv6only is set to 0(default in most distros), an application binding an AF_INET6 listening socket to "any" will receive on the same socket IPv4 connections as well. However, this can be reproduced by using the same port and starting one pgrst with ::1 as server-host and another with 127.0.0.1.

[steve-chavez]

A quick way to solve this would be changing the default host to 127.0.0.1, that way the second pgrst process would get the Address already in use error.

However the underlying issue is that we're not using SIGHUP for quitting the process, I think apache/nginx can get away with using SIGHUP to reload because they log to a file and don't face the stdout problem, for example starting pgrst with postgrest config > pgrst.log and then closing the terminal window doesn't make the server fail.

So to summarize, the options for solving this are:

• Change default of *4 to 127.0.0.1
• Leave SIGHUP with it's default behavior of quitting the process, use SIGUSR1 to reload the schema instead.
• Log to a file by default instead of stdout.