Non standalone version starts returning 504 error and requires restart

[struan]

See mysociety/popit#719 for some details on the original site.

This doesn't happen immediately but after a while the proxy starts returning 504 errors and then continues to do so until the node process is restarted.

This only seems to happen for images that are hosted on the same app as the proxy is included in so I'm assuming it's something in the interaction that's causing this. The images are served fine when not called via the proxy.

I'm mostly raising this in case someone else has come across similar behaviour.

[chrismytton]

@jpmckinney I think we've tracked down the problem thanks to your hint about increasing the maxSockets option.

It seems that occasionally, for whatever reason, a request to the image-proxy is closed before it has completed. This appears to fill up the http.globalAgent.sockets array for the hostname:port of the image. To test this I added some debugging (mysociety@44ff24c), requested a large image via the proxy using curl (http://localhost:5000/http%3A%2F%2Fgoes.gsfc.nasa.gov%2Fpub%2Fgoes%2F080913.ike.poster.jpg/200/0) and then closed the request before completion by hitting ctrl-c. After repeating this a few times I saw this output:

{ domain: null,
  _events: { free: [Function] },
  _maxListeners: 10,
  options: {},
  requests: {},
  sockets: { 'goes.gsfc.nasa.gov:80': [ [Object], [Object] ] },
  maxSockets: 5,
  createConnection: [Function] }
{ domain: null,
  _events: { free: [Function] },
  _maxListeners: 10,
  options: {},
  requests: {},
  sockets: { 'goes.gsfc.nasa.gov:80': [ [Object], [Object], [Object] ] },
  maxSockets: 5,
  createConnection: [Function] }
{ domain: null,
  _events: { free: [Function] },
  _maxListeners: 10,
  options: {},
  requests: {},
  sockets: { 'goes.gsfc.nasa.gov:80': [ [Object], [Object], [Object] ] },
  maxSockets: 5,
  createConnection: [Function] }
{ domain: null,
  _events: { free: [Function] },
  _maxListeners: 10,
  options: {},
  requests: {},
  sockets: { 'goes.gsfc.nasa.gov:80': [ [Object], [Object], [Object], [Object] ] },
  maxSockets: 5,
  createConnection: [Function] }
{ domain: null,
  _events: { free: [Function] },
  _maxListeners: 10,
  options: {},
  requests: {},
  sockets: { 'goes.gsfc.nasa.gov:80': [ [Object], [Object], [Object], [Object], [Object] ] },
  maxSockets: 5,
  createConnection: [Function] }

As you can see, the requests that are closed before completion aren't removed from the sockets array for the hostname:port when the request is closed.

I found the solution here - nodejs/node-v0.x-archive#6227 (comment), basically .abort()ing the request to the proxied image when the incoming request is closed seems to solve the problem.

So this commit - mysociety@5e304b5 - solves the unclosed socket issue, hooray!.

However there are two issues that I am having trouble resolving:

1. I get errors from imagemagick when the request is aborted:

   convert: Premature end of JPEG file `/var/tmp/magick-587761gbXLZM7kJq' @ warning/jpeg.c/JPEGWarningHandler/352.
   convert: Premature end of JPEG file `/var/tmp/magick-587761gbXLZM7kJq' @ error/jpeg.c/JPEGErrorHandler/322.
   convert: no images defined `-' @ error/convert.c/ConvertImageCommand/3187.
   

2. I have no idea what the best way to test this is!

[jpmckinney]

I've added the commit for now. I haven't been able to reproduce the imagemagick error.

c092cee

[jpmckinney]

I've just pushed an alternate solution that simply doesn't use connection pooling, like substack's hyperquest library, to get around the maxSockets growth/limit. The abort() is what was causing the ImageMagick to fail. As it happens, connection pooling combined with a low maxSockets was causing tests to fail originally, so the solution is basically tested by the fact that the tests succeed.

[chrismytton]

@jpmckinney Ah that looks promising, thanks! I've deployed the latest master of image-proxy to popit production. I'll monitor it until the end of the week and let you know if we encounter any further issues.

[jpmckinney]

Sounds good. I'll close this issue, but can re-open if the error isn't resolved.

[jpmckinney]

If there are no issues by the end of the week, let me know, and I'll release 0.0.3.

[chrismytton]

@jpmckinney We've had no further issues, so I think you're clear to release 0.0.3. Thanks!

[jpmckinney]

Thanks - it's released!