{"action":"closed","issue":{"url":"https://api.github.com/repos/joyent/node-cueball/issues/25","repository_url":"https://api.github.com/repos/joyent/node-cueball","labels_url":"https://api.github.com/repos/joyent/node-cueball/issues/25/labels{/name}","comments_url":"https://api.github.com/repos/joyent/node-cueball/issues/25/comments","events_url":"https://api.github.com/repos/joyent/node-cueball/issues/25/events","html_url":"https://github.com/joyent/node-cueball/issues/25","id":178720974,"number":25,"title":"race during connection teardown leaves HTTP request hung","user":{"login":"davepacheco","id":532688,"avatar_url":"https://avatars.githubusercontent.com/u/532688?v=3","gravatar_id":"","url":"https://api.github.com/users/davepacheco","html_url":"https://github.com/davepacheco","followers_url":"https://api.github.com/users/davepacheco/followers","following_url":"https://api.github.com/users/davepacheco/following{/other_user}","gists_url":"https://api.github.com/users/davepacheco/gists{/gist_id}","starred_url":"https://api.github.com/users/davepacheco/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/davepacheco/subscriptions","organizations_url":"https://api.github.com/users/davepacheco/orgs","repos_url":"https://api.github.com/users/davepacheco/repos","events_url":"https://api.github.com/users/davepacheco/events{/privacy}","received_events_url":"https://api.github.com/users/davepacheco/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":3,"created_at":"2016-09-22T21:08:56Z","updated_at":"2016-11-11T00:22:30Z","closed_at":"2016-11-11T00:22:30Z","body":"This is somewhat related to #24.  While integrating cueball into the Marlin agent as part of [MANTA-2872](http://smartos.org/bugview/MANTA-2872), I ran into a case where an HTTP request was dropped by the Cueball agent.  In this case, there's a request being made from the Marlin lackey (inside a non-global zone) over a Unix Domain Socket to the Marlin agent (in the global zone), which is proxying that request over a TCP connection to the Manta loadbalancer (in a different non-global zone):\n\n```\n            UDS               TCP\n lackey   +------>  marlin  +------> loadbalancer\n                    agent\n```\n\nI'm modifying the Marlin agent to use the Cueball HTTP agent for making the upstream request to the loadbalancer.  Here's the timeline, based on log files:\n\n```\n17:51:10.005Z lackey reports \"put: entered\" -- it starts making the request\n17:51:37       Z the request still hasn't completed, so I save a core file of the marlin agent\n17:53:10.021Z lackey reports a \"socket hang up\" from Node -- this is likely the default 2-minute socket timeout\n```\n\nThis request never made it to the loadbalancer or to muskie.  I've uploaded the core file as thoth dump 9768105b15d6b2e808e0abe25828ec02.  From the core file:\n- The outgoing client request is in the core file at `bc021d99`.  It refers to the cueball agent (as expected).\n- The outgoing client request has no socket on it.\n- The cueball pool (`bc0b3dc5`) is \"running\" and shows no dead connections.\n- The pool has 16 connections on p_idleq and 0 requests on p_waiters.\n\nSince there are idle sockets and no waiting requests, but our request has not had a socket assigned to it, this seems like a missed wakeup.  To confirm that, I looked to see if I could figure out whether the HttpAgent's claim() callback had been called.  `bc0b8f81` appears to be the closure for constructSocket() from lib/agent.js line 116.  The \"waiter\" variable in that scope looks like this:\n\n```\n\"waiter\": bc021dd9: {\n    \"cancel\": 9fd3ef25: function <anonymous> (as handle.cancel),\n    \"error\": 9a408091: undefined,\n    \"reply\": 9a408091: undefined,\n}\n```\n\nBased on the code, this value would be \"undefined\" if the claim() callback had been invoked.  The fact that \"waiter\" has \"reply\" and \"error\" properties means that when the request was issued, there were no idle sockets, so the request would have been queued onto p_waiters.  Since that queue is empty now, at some point we dequeued it, but didn't finish claiming a socket for it.\n\nI found that there are 25 ConnectionFSM objects, and only one of them has `cf_claimed == true`: `bc032901`.  This FSM has a listener for the the \"stateChange\" event for state \"busy\", and by following closures I found that this is our missed wakeup: this closure ultimately refers to the request that was dropped.\n\nThe history for this FSM is surprising:\n\n```\n> bc032901::jsprint fsm_history\n[\n    \"init\",\n    \"connect\",\n    \"idle\",\n    \"closed\",\n    hole,\n    hole,\n    hole,\n    hole,\n    hole,\n    hole,\n    hole,\n    hole,\n    hole,\n    hole,\n    hole,\n    hole,\n    hole,\n]\n```\n\nNow, since `cf_claimed == true` we know that we called `fsm.claim()`, and `fsm.claim()` has an assertion that it's invoked in state \"idle\".  But `fsm.claim()` synchronously emits 'claimAsserted', which for the \"idle\" state normally transitions us to \"busy\".  That didn't happen here, because \"busy\" is not in fsm_history, nor is it in fsm_nextState.  The only way I could see that this could happen is if we never set up the \"claimAsserted\" handler when we entered the \"idle\" state, which happens if cf_closeAfter is set.  That in turn happens if `closeAfterRelease()` is called before we enter \"idle\".\n\nSo here's a possible sequence of events that I think would cause this:\n1. Assume a ConnectionFSM is in state \"connecting\".\n2. For some reason, maybe as part of `rebalance()`, we call `closeAfterRelease()` on the FSM, setting `cf_closeAfter = true`.\n3. When the connection is established, we transition to 'idle'.  Because cf_closeAfter is true, we call `gotoState('closed')`.  That transition is deferred because we're currently transitioning.  We do _not_ add a 'claimAsserted' listener because `state_idle()` bails out before doing that in this case.\n4. `state_idle()` returns, and `gotoState` (still in the call to transition to \"idle\") emits 'stateChange', which fires the handler that gets set up in addListener().  This finds a waiting request and a newly-idle connection and calls `fsm.claim()`. The assertion passes because the FSM is still in state \"idle\", a listener is added for the stateChange to \"busy\", and we emit \"claimAsserted\", but nothing is listening for this event.\n5. `fsm.claim()` returns.  The stateChange event handler completes.\n6. Back in `gotoState` (still for the transition to \"idle\"), we see that nextState is 'closed' because of the transition that was deferred in step 3 and call `gotoState('closed')`.\n\nThis explains all the data points: the FSM comes to rest in the \"closed\" state with `cf_claimed == true`, the request has been dequeued from p_waiters, but the HttpAgent's `claim()` callback has not been invoked (and will never be invoked).  The only question is about (2) -- why would we have closed an FSM during initialization?\n\nI reproduced this while running \"bunyan -p\", and here are the Cueball log entries:\n\n```\n16:26:40.493Z TRACE MarlinAgent/CueballAgent: skipping v6 lookup for d5d07015-2c7c-4da2-a831-e31a54252907.manta.emy-10.joyent.us, using additionals from SRV (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3)\n16:26:40.494Z TRACE MarlinAgent/CueballAgent: skipping v6 lookup for 4409d3c7-f837-41e9-9d84-7269d8b96d4f.manta.emy-10.joyent.us, using additionals from SRV (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3)\n16:26:40.494Z TRACE MarlinAgent/CueballAgent: skipping v4 lookup for d5d07015-2c7c-4da2-a831-e31a54252907.manta.emy-10.joyent.us, using additionals from SRV (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3)\n16:26:40.494Z TRACE MarlinAgent/CueballAgent: skipping v4 lookup for 4409d3c7-f837-41e9-9d84-7269d8b96d4f.manta.emy-10.joyent.us, using additionals from SRV (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3)\n16:26:40.496Z TRACE MarlinAgent/CueballAgent: host added: QfmdPIZyaZSnKdPyW3J2VVrciww= (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3)\n16:26:40.497Z TRACE MarlinAgent/CueballAgent: rebalancing pool, remove 0, add 17 (busy = 0, spares = 0, target = 17) (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3)\n16:26:40.506Z TRACE MarlinAgent/CueballAgent: host added: YBFi11WbMFZdCMgL2yES5HV/Jek= (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3)\n16:26:40.506Z TRACE MarlinAgent/CueballAgent: rebalancing pool, remove 8, add 8 (busy = 1, spares = 16, target = 17) (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3)\n16:26:40.506Z TRACE MarlinAgent/CueballAgent: ConnectionFSM closed (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.507Z TRACE MarlinAgent/CueballAgent: ConnectionFSM closed (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.507Z TRACE MarlinAgent/CueballAgent: ConnectionFSM closed (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.507Z TRACE MarlinAgent/CueballAgent: ConnectionFSM closed (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.508Z TRACE MarlinAgent/CueballAgent: ConnectionFSM closed (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.508Z TRACE MarlinAgent/CueballAgent: ConnectionFSM closed (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.508Z TRACE MarlinAgent/CueballAgent: ConnectionFSM closed (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.512Z TRACE MarlinAgent/CueballAgent: sleeping until next TTL expiry (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, state=srv, delay=4981)\n16:26:40.538Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.539Z TRACE MarlinAgent/CueballAgent: ConnectionFSM closed (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.540Z TRACE MarlinAgent/CueballAgent: rebalancing pool, remove 1, add 0 (busy = 0, spares = 17, target = 16) (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3)\n16:26:40.540Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.540Z TRACE MarlinAgent/CueballAgent: ConnectionFSM closed (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.541Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.541Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.541Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.541Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.542Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.542Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.542Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.542Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=QfmdPIZyaZSnKdPyW3J2VVrciww=)\n16:26:40.542Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=YBFi11WbMFZdCMgL2yES5HV/Jek=)\n16:26:40.543Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=YBFi11WbMFZdCMgL2yES5HV/Jek=)\n16:26:40.543Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=YBFi11WbMFZdCMgL2yES5HV/Jek=)\n16:26:40.552Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=YBFi11WbMFZdCMgL2yES5HV/Jek=)\n16:26:40.553Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=YBFi11WbMFZdCMgL2yES5HV/Jek=)\n16:26:40.553Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=YBFi11WbMFZdCMgL2yES5HV/Jek=)\n16:26:40.553Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=YBFi11WbMFZdCMgL2yES5HV/Jek=)\n16:26:40.554Z TRACE MarlinAgent/CueballAgent: connected, idling (domain=manta.emy-10.joyent.us, service=_http._tcp, pool=98c3e574-84e8-43a9-a7a6-d347381024c3, backend=YBFi11WbMFZdCMgL2yES5HV/Jek=)\n```\n\nIt looks like we closed some FSMs during initialization as part of rebalancing as we discovered new backends and adjusted the number of connections to each backend.  There's nothing really wrong with that.\n\nIt seems that we went off the rails when we attempted to call FSM.claim() on something that had a deferred transition to \"closed\".  This is pretty different from #24, but it's similar in that the addListener() \"stateChange\" event handler is reacting to a state change that's been obviated by another state change that's been deferred.\n\nIt might also be useful to have a stress test that sets up several backends corresponding to different servers running in the same process, runs a continuous workload of requests against them, periodically adds and removes backends, and makes sure that no request ever fails.\n"}}
{"actor":{"display_login":"davepacheco"}}