@othiym23 do you still have the wireshark dumps around?

I do. I'll figure out some way to share them and put a link here.

@janl https://github.com/othiym23/debugging-npm-couchdb-iojs

These captures comprise only the initial population of the VDUs into the new Couch database and the potentially failing auth calls. There are, right now, two traces – one with keep-alive enabled, and one without. The former fails and the latter succeeds.

Let me know if you want any other traces. Capturing them is pretty easy for me now.

It looks like there don't need to be auth failures in order to see the problem. I am running with a modified version of 01-adduser, and it still fails when I do this:

test('adduser a', fn.bind(null, conf, u))
test('adduser b', fn.bind(null, conf, u))
test('adduser c', fn.bind(null, conf, u))
test('adduser d', fn.bind(null, conf, u))

It looks like the first login attempt is handled in about a half a second, and every subsequent one is delayed by 10 seconds. The '10' is suspiciously round, so it may be a timeout or some such.

@othiym23 can you post your recipe for gathering the packet dumps? I want to see what's going on in my reduced example (above).

1. Fire up wireshark, and start a capture with a filter to pay attention to only port 15986.
2. Physically move aside all the tests except setup, auth, and teardown.
3. Run the tests.
4. Stop the wireshark capture session.

There are some example captures at the repo I mentioned to janl above.

That timeout is the retry built into npm-registry-client, and happens because connections on the keep-alive socket fail. What I haven't been able to figure out is why there are duplicate FINs and / or ACKs from the CouchDB side -- the error appears to be at the TCP, rather than HTTP, layer.

I think, at least part of this problem, is a couchdb issue. From looking at the dumps, it simply decides to end the connection after sending the response even though it did not specify this intention in the response (by adding a connection: close header).

Btw, I found https://issues.apache.org/jira/browse/COUCHDB-1146, which seem related. Maybe @jhs can elaborate?

I agree, the problem seems to be on the second sending of any given credential. The couchapp returns 409, and then for some reason couchdb throws in the RST and kills the connection.

@kanongil That agrees with my reading of the CouchDB source, which is that this error at root is something funky in mochiweb's handling of keep-alive (and also with the fact that prior to Node.js 0.12 / io.js, Node didn't actually have a working keep-alive implementation in its http.Agent code). I need a minimal reduction that I can take to @janl et al to get it fixed, or some kind of patch to mochiweb, both of which have proven to be a bit tricky to get.

Can we reproduce the problem with clients other than node > 0.11 ? I am curious about this, which I see just before the RST:

166   2.240033    127.0.0.1 -> 127.0.0.1    TCP 56 62249→15986 [ACK] Seq=977 Ack=787 Win=407488 Len=0 TSval=1247001303 TSecr=1247001303
167   2.240067    127.0.0.1 -> 127.0.0.1    TCP 56 15986→62249 [FIN, ACK] Seq=787 Ack=977 Win=325664 Len=0 TSval=1247001303 TSecr=1247001303
168   2.240082    127.0.0.1 -> 127.0.0.1    TCP 56 62249→15986 [ACK] Seq=977 Ack=788 Win=407488 Len=0 TSval=1247001303 TSecr=1247001303

It looks like the client (port 62249) ACK's two packets (787, 788) using the same sequence number (977). Is that a correct reading, and if so, is that legitimate TCP?

https://blog.udemy.com/tcp-dupack/

As it stands, this is just more evidence of weirdness in the interaction between CouchDB and Node.

I have a little libcurl C program that sends the same requests as npm adduser should be sending, except for the very last one (the update). So far I have not been able to trigger the RST. Note that curl uses keepalive by default, and the wireshark dumps of my little script seem to confirm that.

Does this prove anything by itself? Should I try to compare the data sent by curl to the data sent by npm-registry-client, packet-by-packet?

Should I try to compare the data sent by curl to the data sent by npm-registry-client, packet-by-packet?

If you can.

If it helps (it probably doesn't), this is a race of some kind, because the npm-registry-couchapp tests do not fail 100% of the time, and in if my machine is chugging because it's been a while since I rebooted or I did something that caused it to have to do a lot of swapping, that slows the tests down enough that they fail much less frequently. So I'd try playing with the timing of events in your test client, and maybe have it do some of its requests on concurrent keep-alive connections. I suspect, but was unable to establish to my satisfaction, that part of the problem may be mochiweb getting confused about which responses go to which connections in the case of concurrent clients on the same IP.

Ah, OK. So the ideal case is to have two curl processes launched back-to-back:

1. sets user (exercise user-not-present pathway)
2. attempts to set user, winds up updating (exercise 409 pathway)

That will precisely mimic what's happening in 01-adduser, when it launches two npm adduser commands in a row.

I'm pretty sure the RST is sent because node sends a packet after the response has been transmitted, and a FIN has been sent and merely indicates that couchdb has called close() on the socket. Also, this explains the race condition, where everything will be ok when node transmits the remaining packet data before couchdb responds.

Okay, here's some more data.

When I run the npm adduser commands through the tap test suite, I get the error. When run the test suite with a "wait" command, holding the registry open, I can run npm adduser from the command line, using

$  npm --registry=http://127.0.0.1:15986/ --userconf=bad.conf adduser < npm-adduser.in 

This also fails in the same way, with an extra packet sent from node to couch, follwed by an RST sent from couch. So the failure appears to be in the way node behaves with the keepalive socket:

first, in that it writes to the socket after it is FIN/ACK'd
second, in that it ignores the RST sent by the server

As far as which commits introduced this into node, I am currently looking at: libuv/libuv@e19089f

and trying a locally built IOJS without the out-of-band support that was added for 1.4.2, 1.4.3 on Darwin.

@othiym23 can you reproduce this bug with io.js on other, non-Darwin platforms?

No, that out of band stuff is fine - or rather, removing it does not remove the problem

I believe npm/npm-registry-client#107 fixes this. ;-)

Long writeup:

As usual, a complicated bug stems from multiple causes. In this case there are at least two underlying bugs.

First, npm-registry-client/lib/adduser.js sends { body: userobj } with every request it makes to the registry. This is fine when the request is a PUT (as it is for the first and third requests) but incorrect when the request is a GET. This bug has been present since Oct 31, 2014 but has been harmless since writing to a dead socket is allowed and ignored. (Bug was introduced by this commit: npm/npm-registry-client@29a21d0^1...29a21d0#diff-ca9f3ace6b674b53393b3d9678233b68R64 )

Second, there is at least one bug, possibly more, in the new http-keepalive code added in io.js and node >= 0.12. The first problem is recycling a socket when there are still writes pending against it. Here the problem was that the HTTP agent sent the GET request, and followed by writing the {body} specified by npm-registry-client. However, before the write was executed, the request had been received, processed, and responded to, so the http-keepalive code in iojs/lib/_http_agent.js placed the socket on the freeSocket list. Then, the next request was queued, taking the socket back off of the freeSocket list.

The code that initializes a socket for HTTP use in iojs/lib/_http_client.js uses a one-tick delay. In this case, I was able to see the write coming directly in between the first call (onSocket) and the one-tick-delayed call (tickOnSocket):

HTTP 72584: agent.on(free) 127.0.0.1:15986::
HTTP 72584: removeSocket 127.0.0.1:15986:: destroyed: false
HTTP 72584: have free socket
HTTP 72584: clean up free socket queue

[1] HTTP 72584: onSocket 

[2] HTTP 72584: write wrote = {"_id":"org.couchdb.user:user","name":"user","password":"pass@:\\'","email":"[email protected]","type":"user","roles":[],"date":"2015-04-14T18:49:04.598Z","_rev":"1-0ae8131bcafaf125da4424dfcc3fe7d8","password_scheme":"pbkdf2","iterations":10,"derived_key":"f1733252f704715c9d817859085c206be1c5c77f","salt":"6b76129f88db291761ac2c44f73caf2f"}

HTTP 72584: write ret = false
HTTP 72584: outgoing message end.

[3] HTTP 72584: tickOnSocket  18

[4] NET 72584: onread -54

NET 72584: nread = -54, destroying..
NET 72584: destroy
NET 72584: close
NET 72584: close handle
HTTP 72584: SOCKET ERROR: read ECONNRESET Error: read ECONNRESET
    at exports._errnoException (util.js:749:11)
    at TCP.onread (net.js:528:26)

The first few lines of the log show the socket being cleaned up and discarded (returned to the pool, for a keepalive socket). Then the socket is queued for configuration in step [1] (onSocket). Next, the previously queued write is processed on the socket [2]. On the next tick the socket is available to actually be configured by the code in tickOnSocket [3]. Meanwhile, the other end of the connection has received garbage data (the body data associated with the previous GET request), which causes it to send an RST packet (TCP Reset). The RST is not handled in the iojs networking layer, which causes it to propagate up into the the http and application layer.

Eventually the npm-registry-client code times out, declares an error, and retries the request. Because there is no longer a write pending, the retry succeeds.

The error (or errors) in the iojs networking / keepalive code are:

1. allowing a write to socket that has been recycled via keepalive
2. not handling the RST on the http keepalive socket.

Unfortunately I don't have any ideas for how to fix those easily. If low-level uv primitives can tell whether writes are pending on a socket — or, even better, cancel all writes pending on a socket — then point 1 may be fixable.

Regarding point 2, the meaning of tcp reset is well defined on an HTTP keepalive socket -- it means, re-initialize your listener and return this socket to the pool. Unfortunately the error is being detected and handled in net.js and the HTTP keepalive code lives in _http_agent.js, so it's hard to see how to handle this without mixing the concerns of simple TCP sockets and http keepalive sockets.

However the iojs issues are addressed, though, the trigger can be removed from npm-registry-client by patching npm/npm-registry-client#107, which will remove this test failure from npm's integration tests.

sam u r the best 😘

@chrisdickinson and @indutny, you might find #7699 (comment) interesting. Also, @janl, I think this lets CouchDB off the hook. I'm going to test and potentially land this patch now.

npm/npm-registry-client@856eefe contains the fix for this, and 431c3bf includes the fixed version of npm-registry-client. Yay! I am so glad this is fixed! THANK YOU SAM

Glad this is resolved :)

Impeccable sleuthing @smikes!

@othiym23 let me know if anything else seems fishy on the CouchDB end.