4

My express app drops some requests intermittently. I've debugged it to a point where I see a server socket close before the router finishes processing. Here's a log snippet.

  [ 'Host',
     '<redacted>',
     'Host',
     '<redacted>',
     'X-Real-IP',
     '122.171.219.142',
     'X-Forwarded-For',
     '122.171.219.142',
     'X-Forwarded-server',
     '<redacted>',
     'X-Forwarded-uri',
     '/files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576',
     'X-Forwarded-Proto',
     'https',
     'Connection',
     'upgrade',
     'accept',
     'application/json, text/javascript, */*; q=0.01',
     'accept-encoding',
     'gzip, deflate, sdch',
     'accept-language',
     'en-US,en;q=0.8',
     'cookie',
     '<redacted>',
     'referer',
     'https://<redacted>/files/upload',
     'user-agent',
     'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.81 Safari/537.36',
     'x-requested-with',
     'XMLHttpRequest' ],
  url: '/files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576',
  method: 1,
  versionMajor: 1,
  versionMinor: 1,
  shouldKeepAlive: true,
  upgrade: false }
Fri, 05 Jun 2015 11:30:50 GMT express:router dispatching GET /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
Fri, 05 Jun 2015 11:30:50 GMT express:router query  : /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
Fri, 05 Jun 2015 11:30:50 GMT express:router expressInit  : /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
Fri, 05 Jun 2015 11:30:50 GMT express:router jsonParser  : /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
Fri, 05 Jun 2015 11:30:50 GMT express:router urlencodedParser  : /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
Fri, 05 Jun 2015 11:30:50 GMT express:router <anonymous>  : /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
Fri, 05 Jun 2015 11:30:50 GMT express:router <anonymous>  : /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
Fri, 05 Jun 2015 11:30:50 GMT express:router <anonymous>  : /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
Fri, 05 Jun 2015 11:30:50 GMT express:router cookieParser  : /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
Fri, 05 Jun 2015 11:30:50 GMT express:router <anonymous>  : /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
HTTP 1735: server socket close
Fri, 05 Jun 2015 11:30:50 GMT express:router <anonymous>  : /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
Fri, 05 Jun 2015 11:30:50 GMT express:router <anonymous>  : /files/upload/progress?id=8dd96bd094914981951c28855962f38e&_=1433503852576
HTTP 1735: write ret = false
HTTP 1735: write ret = false
HTTP 1735: outgoing message end.

I get a 502 response and Nginx error log shows upstream prematurely closed connection. In all other successful requests, the write ret happens before the server socket close and both happen after all the router logs.

Node version is 0.12.4 Express version is 4.12.4

This log was generated with NODE_DEBUG=http DEBUG=express:*

Any pointers on how to continue debugging will be highly appreciated!

Dave Newton
  • 158,873
  • 26
  • 254
  • 302
braindead
  • 171
  • 6

0 Answers0