Repository navigation
Connection dropped/timed out when connecting to deployed agent #414
Description
Describe the bug
Occasionally, when attempting to connect to a deployed agent, we see connection timeouts. Sometimes, this also results in a connection being dropped (and shutting down both agents if the connection is attempted during pk agent start with the deployed agent specified as a seed node). A specific occurrence of both agents shutting down ended with this error on the local agent:
{"type":"ErrorPolykeyRemote","data":{"message":"","timestamp":"2022-07-13T06:34:55.448Z","data":{},"cause":{"type":"ErrorPolykeyRemote","data":{"message":"","timestamp":"2022-07-13T06:34:55.409Z","data":{},"cause":{"type":"ErrorConnectionStartTimeout","data":{"message":"","timestamp":"2022-07-13T06:34:55.363Z","data":{},"description":"Connection start timed out","exitCode":68}},"description":"Remote error from RPC call","exitCode":68,"metadata":{"nodeId":"v5neee032adia1v5u8lj483hhb5bp45ejb8knlmtbuei00lvupudg","host":"54.206.24.79","port":1314,"command":"nodesHolePunchMessageSend"}}},"stack":"ErrorPolykeyRemote\n at toError (/home/emma/Projects/js-polykey/src/grpc/utils/utils.ts:203:29)\n at Object.callback (/home/emma/Projects/js-polykey/src/grpc/utils/utils.ts:381:17)\n at Object.onReceiveStatus (/home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/client.ts:351:26)\n at /home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/call-stream.ts:206:27\n at Object.onReceiveStatus (/home/emma/Projects/js-polykey/src/grpc/utils/FlowCountInterceptor.ts:57:13)\n at InterceptingListenerImpl.onReceiveStatus (/home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/call-stream.ts:202:19)\n at Object.onReceiveStatus (/home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/client-interceptors.ts:462:34)\n at Object.onReceiveStatus (/home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/client-interceptors.ts:424:48)\n at /home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/call-stream.ts:330:24\n at processTicksAndRejections (node:internal/process/task_queues:78:11)","description":"Remote error from RPC call","exitCode":68,"metadata":{"nodeId":"v0ntccuvju21203s05i11jd9o3d35ae08d29csledv3ntpbjjatcg","host":"54.253.9.3","port":1314,"command":"nodesHolePunchMessageSend"}}}
And this series of errors/warnings on the deployed agent:
INFO:NodeConnectionManager:Getting connection to vjrd8n87opao3ctcnirccdo9e6crpq5r92m17umnv9ku00od9vdpg
INFO:NodeConnectionManager:existing entry found for vjrd8n87opao3ctcnirccdo9e6crpq5r92m17umnv9ku00od9vdpg
INFO:NodeConnectionManager:withConnF calling function with connection to vjrd8n87opao3ctcnirccdo9e6crpq5r92m17umnv9ku00od9vdpg
WARN:ConnectionReverse 129.94.8.25:31843:Reverse Error: ErrorConnectionTimeout
INFO:ConnectionReverse 129.94.8.25:31843:Stopping Connection Reverse
WARN:ConnectionForward 129.94.8.25:31843:Forward Error: ErrorConnectionTimeout
INFO:ConnectionForward 129.94.8.25:31843:Stopping Connection Forward
INFO:clientFactory:Destroying GRPCClientAgent connected to 129.94.8.25:31843
INFO:NodeConnection 129.94.8.25:31843:Destroying NodeConnection
INFO:NodeConnection 129.94.8.25:31843:Destroyed NodeConnection
INFO:clientFactory:Destroyed GRPCClientAgent connected to 129.94.8.25:31843
{ "type": "ErrorGRPCClientCall", "data": { "message": "14 UNAVAILABLE: Connection dropped", "timestamp": "2022-07-13T06:35:15.212Z", "data": { "code": 14, "details": "Connection dropped", "metadata": {} }, "stack": "ErrorGRPCClientCall: 14 UNAVAILABLE: Connection dropped\n at toError (/lib/node_modules/@matrixai/polykey/dist/grpc/utils/utils.js:174:24)\n at Object.callback (/lib/node_modules/@matrixai/polykey/dist/grpc/utils/utils.js:331:25)\n at Object.onReceiveStatus (/lib/node_modules/@matrixai/polykey/node_modules/@grpc/grpc-js/build/src/client.js:189:36)\n at /lib/node_modules/@matrixai/polykey/node_modules/@grpc/grpc-js/build/src/call-stream.js:111:35\n at Object.onReceiveStatus (/lib/node_modules/@matrixai/polykey/dist/grpc/utils/FlowCountInterceptor.js:80:29)\n at InterceptingListenerImpl.onReceiveStatus (/lib/node_modules/@matrixai/polykey/node_modules/@grpc/grpc-js/build/src/call-stream.js:106:23)\n at Object.onReceiveStatus (/lib/node_modules/@matrixai/polykey/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:365:141)\n at Object.onReceiveStatus (/lib/node_modules/@matrixai/polykey/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:328:181)\n at /lib/node_modules/@matrixai/polykey/node_modules/@grpc/grpc-js/build/src/call-stream.js:187:78\n at processTicksAndRejections (node:internal/process/task_queues:78:11)", "description": "Generic call error", "exitCode": 69 } }
To Reproduce
The exact cause of the error is still unknown, however, it may be reproducible by connecting to a deployed agent as a seed node npm run polykey -- agent start --seednodes="[deployedAgentNodeId]@[deployedAgentHost]:[deployedAgentPort] --verbose --format json
Expected behavior
Even if a connection times out, this shouldn't kill an agent, especially not the seed node. The seed node should be able to ignore a failed connection, even if it was the cause of the failed connection, since we need seed nodes to be stable.
Activity
emmacasolin commentedon Jul 14, 2022
Interestingly, I'm having a lot less difficulty connecting to deployed agents on my home wifi compared to uni wifi, and I haven't had the connection dropped like it was yesterday. This may just be our agents not being able to punch through stronger NATs, so this issue may be relevant when it comes to working on #383
CMCDragonkai commentedon Jul 14, 2022
The testnet isn't behind any NAT. It has public IP addresses, when connecting from local agent to the testnet, there's isn't any punch through. As soon as your local agent initiates a message, your local NAT would allow reverse packets from the same IP+port.
emmacasolin commentedon Jul 14, 2022
Yes, I meant in the case of the testnet trying to connect back to me. If the conntrack entry has expired then the testnet would not be able to reach me, if that's indeed what it's attempting to do. These connection re-attempts (coming from the testnet) are continuing for 20+ hours after my local agent was killed, probably longer, but that's the longest any of the agents showing this behaviour have been active.
CMCDragonkai commentedon Jul 14, 2022
Ah yes, that can happen.
Now that I think about it. What is the reason for the testnet attempting to connect back? It has something to do with DHT queries I believe, but in that case, one must expect failures to reconnect in case your local node goes offline. Is the connection attempt solely at the proxy level (proxy connection), or at the grpc connection level (node connection)?
Are there are other reasons? @tegefaulkes
For punching back to your local node, you have to have #383 done too. Plus your node is pretty transient since it's both mobile on the Uni wifi network, and then the Uni network itself would have a NAT. Note that #383 isn't solely about 2 levels of NATs, but really any number of levels of NATs.
Tailscale/tailnet is good source of inspiration for how to address some of this.
CMCDragonkai commentedon Jul 14, 2022
Furthermore if reconnection attempts fail for any arbitrary node on the network, these may make very noisy logs, because there would lots of failed network connection attempts in the future as the network scales. I reckon structured logging will need to be made use of to help filter out these logs.
emmacasolin commentedon Jul 14, 2022
While my agent is online the connection attempts are at the grpc connection/node connection level, but once it goes offline I believe it's only at the proxy level (since the only logs are coming from
ConnectionForward).tegefaulkes commentedon Jul 14, 2022
AFAIK the only times a node will automatically try to connect to another node is
syncNodeGraph.pingNodeonly opens a proxy connection and not a fullnodeConnection.If the nodes are continuously trying to connect over and over again then I'd check
CMCDragonkai commentedon Sep 14, 2022
This problem is similar to #418. This may also be an unhandled promise rejection.
I believe our PK agent should have a unhandled promise rejection handler registered at the top level. And if it receives it, should report it appropriately and also exit the program. We should have this done inside
bin/polykey-agent.ts.At the moment there is no unhandled promise rejection handler.
We can add this in to aid in our debugging.
At the same time, we could also address: #307.
See: https://nodejs.org/api/process.html#event-unhandledrejection
We should have 2 new exceptions at the top level:
These 2 indicate software bugs, so they should use
sysexits.SOFTWAREas the sysexit code.Actually I just remembered
bin/utils/ExitHandlers. This is actually being registered for signals, but not for those problems. So the implementation of these handlers should be done inExitHandlers.CMCDragonkai commentedon Sep 14, 2022
I don't have a solution for this bug yet, @tegefaulkes can add the handlers, and let's see if we reproduce AFTER we have solved the other bugs #418 and #415.
tegefaulkes commentedon Sep 16, 2022
I just looked,
src/bin/utils/ExitHandlers.ts:111already registers handlers forunhandledRejectionanduncaughtException. The handler prints the error tostderrand exits the process. So this is already being handled.Right now it will set the process exitcode to the error's code if it's an
ErrorPolykey. Otherwise the code is set to 255 before exiting. It doesn't nonErrorPolykeyerrors into anything else. There doesn't seem to be a need for it.With #414 (comment) already addressed then I don't know what else to do for this issue.
tegefaulkes commentedon Sep 16, 2022
I could resolve #307 for detecting promise deadlocks.
CMCDragonkai commentedon Sep 16, 2022
Yes the
ExitHandlerhaserrorHandlerproperty being used for bothunhandledRejectionanduncaughtException.However we want to change this to rethrow a special set of exceptions: #414 (comment)
So that it is clear to us that these are unrecoverable errors. In fact, the presence of these indicate a software bug.
CMCDragonkai commentedon Sep 16, 2022
Since they are all unrecoverable errors, we can use
sysexits.SOFTWAREas the software bug code.Regardless of whether it is an instance of
ErrorPolykeyor not, it should be wrapped up.We should not use
ErrorPolykeyprefix here. These are actually not about PK at all. They are nodejs runtime problems.I suggest we putting all of these exceptions into the
ExitHandlersclass itself.tegefaulkes commentedon Sep 20, 2022
We don't want these errors to extend
ErrorPolykeywe need a different error to extend. CurrentlyErrproPolykeyis the base class we use to create all of our errors and it's the class that adds theexitCodeanddescriptionproperties.I'm going to rename
ErrorPolykeytoGenericError(or whatever is a better name) and haveErrorPolykeyand the other errors above extend that.tegefaulkes commentedon Sep 20, 2022
I'll hold off on that change for now until I decide the best action.
ErrorGenericbe in it's own file separate fromErrorPolykey.ts?ErrorCLI(ErrorBin) extendErrorPolykeyorErrorGeneric?CMCDragonkai commentedon Sep 20, 2022
Ok well in that case, it should be
ErrorBinUnhandledRejectionandErrorBinUncaughtExceptionandErrorBinAsynchronousDeadlock.And have the
bin/errorsbeErrorBin.CMCDragonkai commentedon Sep 20, 2022
Consider this:
CMCDragonkai commentedon Sep 20, 2022
Change the 2
ErrorNode*insrc/bin/errorsto also beErrorCLI....Also in the
src/errors.ts. What are these 2:CMCDragonkai commentedon Sep 20, 2022
Those last 2 errors, nothing is using those. Must have been forgotten, can be removed.
fix: fixes to errors and adding un-recoverable error handlers
fix: fixes to errors and adding un-recoverable error handlers
fix: fixes to errors and adding un-recoverable error handlers
testnet.polykey.comPolykey-CLI#71