davepacheco
commented
6 years ago In a brief run, here's the distribution of haproxy status codes and termination states found:
$ pbpaste | awk '{print $9, $13 }' | sort | uniq -c
1 -1 CH--
68 200 ----
57 204 ----That's 68+57 successful GETs and PUTs (200 and 204 status codes) with normal terminations, plus one more problematic entry. Also of note is that this run (which was directed at one loadbalancer) had a lot more than one error:
$ LOG_LEVEL=trace ./bin/mlive -s 2 -S 15 2>log.out
2018-03-13T20:04:01.679Z: reads okay, writes okay (6/6 ok since start)
2018-03-13T20:04:16.710Z: all okay (155/155 ok since 2018-03-13T20:04:01.679Z)
2018-03-13T20:04:26.724Z: all partial_outage (98/105 ok since 2018-03-13T20:04:16.710Z)
2018-03-13T20:04:27.726Z: all okay (6/6 ok since 2018-03-13T20:04:26.724Z)
2018-03-13T20:04:28.728Z: read partial_outage, write okay (10/11 ok since 2018-03-13T20:04:27.726Z)
2018-03-13T20:04:29.729Z: all okay (8/8 ok since 2018-03-13T20:04:28.728Z)
2018-03-13T20:04:30.731Z: all partial_outage (9/11 ok since 2018-03-13T20:04:29.729Z)
2018-03-13T20:04:31.736Z: read okay, write partial_outage (7/8 ok since 2018-03-13T20:04:30.731Z)
2018-03-13T20:04:34.739Z: all okay (28/31 ok since 2018-03-13T20:04:31.736Z)
2018-03-13T20:04:35.741Z: read partial_outage, write okay (7/10 ok since 2018-03-13T20:04:34.739Z)
2018-03-13T20:04:36.746Z: read okay, write partial_outage (11/13 ok since 2018-03-13T20:04:35.741Z)
$ grep -c 'socket hang up' log.out
319Unfortunately, the interesting haproxy log entry can't be parsed by haplog due to joyent/node-haproxy-log#1, but here's thef ull entry:
2018-03-13T20:04:37+00:00 710f85a9-6f13-4fcf-8f3f-a03c4a508714 haproxy[657137]: ::ffff:172.24.2.24:51143 [13/Mar/2018:20:04:36.746] https secure_api/be0 15/0/1/-1/392 -1 0 - - CH-- 20/4/19/5/0 0/0 "PUT /dap/stor/mlive/mlive_10/obj HTTP/1.1"The haproxy documentation explains that termination state CH-- means:
CH The client aborted while waiting for the server to start responding.
It might be the server taking too long to respond or the client
clicking the 'Stop' button too fast.and specifically, on the two separate characters:
C : the TCP session was unexpectedly aborted by the client.
...
H : the proxy was waiting for complete, valid response HEADERS from the
server (HTTP only).That's certainly strange -- we were waiting on the server, but the client aborted. And we can see that the error happened at 20:04:37, but the TCP connection was only accepted at 20:04:36.746, so there would be no reason for a time out.
jclulow
With a fresh clone using Node 0.10.48 on OS X El Capitan (10.11.6), I see these errors:
During that same period, using a build of the repo from quite a while ago, and the same
nodebinary, I saw no issues:Running with a more verbose log level, we see that the failures look like this:
A similar problem is also reproducible on SmartOS with Node 0.10, but not using Node v4. And although we have recently upgraded loadbalancer images in "master", this problem appears to affect load balancer versions as old as September of last year, which was before those changes. This suggested potentially a client problem -- maybe an updated dependency?
node-mantais the only one that seems likely to affect this behavior.The old build that shows no problems has these dependencies:
It shows a bunch of "invalid" errors because I've apparently pulled down updates without rebuilding, so my packages technically no longer satisfy package.json. My fresh clone looks like this:
I spent some time trying different
node-mantaversions, and I found that the problem was reliably reproducible with node-manta 3.0.0, but not the previous version (2.0.7).