Random Uncaught Exception
Closed this issue · 13 comments
I keep getting a crash randomly with the errors below printed when it happens. This also crashes the whole Node-Red.
I'm using the castv2 simply to get the status of the Chromecast (playing/not playing). The Chromecast works normally and returns ping successfully when this happens.
Node-Red: v2.0.5
Castv2: v4.1.1
[red] Uncaught Exception:
Error: This socket has been ended by the other party
at TLSSocket.writeAfterFIN [as write] (net.js:457:14)
at PacketStreamWrapper.send (/data/node_modules/castv2/lib/packet-stream-wrapper.js:41:15)
at Client.send (/data/node_modules/castv2/lib/client.js:128:11)
at Channel.send (/data/node_modules/castv2/lib/channel.js:34:12)
at fn.Controller.send (/data/node_modules/castv2-client/lib/controllers/controller.js:28:16)
at fn.ConnectionController.disconnect (/data/node_modules/castv2-client/lib/controllers/connection.js:32:8)
at GenericMediaReceiver.Application.close (/data/node_modules/castv2-client/lib/senders/application.js:37:19)
at GenericMediaReceiver.MediaReceiverBase.close (/data/node_modules/node-red-contrib-castv2/lib/MediaReceiverBase.js:25:33)
at CastV2SenderNode.unjoin (/data/node_modules/node-red-contrib-castv2/castv2-sender.js:413:37)
at CastV2ConnectionNode.disconnect (/data/node_modules/node-red-contrib-castv2/castv2-sender.js:176:46)
at PlatformSender.<anonymous> (/data/node_modules/node-red-contrib-castv2/castv2-sender.js:224:30)
at Object.onceWrapper (events.js:482:26)
at PlatformSender.emit (events.js:375:28)
at PlatformSender.emit (domain.js:470:12)
at Client.onerror (/data/node_modules/castv2-client/lib/senders/platform.js:24:10)
at Client.emit (events.js:375:28)
at Client.emit (domain.js:470:12)
at TLSSocket.onerror (/data/node_modules/castv2/lib/client.js:48:10)
at TLSSocket.emit (events.js:375:28)
at TLSSocket.emit (domain.js:470:12)
at emitErrorNT (net.js:1347:8)
at processTicksAndRejections (internal/process/task_queues.js:82:21)
There is already an exception catch around this call.
I'm not sure what else I can do here really without a way to reproduce. When is this happening to you? Are your cast targets power cycling for some reason?
I haven't been able to reproduce it reliably and it's completely random when it happens. No power cycling or anything happening. Also the network seems to be error free according to the logs (using UniFi AP's and Controller).
It seems it's most likely to happen when something is beginning to be casted to the Chromecast (activating the casting but not actually playing something). But I can't reliably reproduce it by casting something.
I also tried a simple mp3 url media play to Chromecast using the castv2 and it also causes the same issue but randomly. Seems to happen more easily if the Chromecast has gone idle before trying to play something again.
The only real problem is that the exception crashed the Node-Red. Sorry I can't narrow it down further but I'll keep looking/testing.
I've dug a bit and here's what I think is happening.
The underlying castv2 library is a little finicky. To avoid it leaving a bunch of open event handles, you kind of have to call a bunch of close / disconnect methods to clean things up before trying to reconnect to avoid these. As such, when the main client has an error, or disconnects, I have to loop over the attached Receiver apps in each node and gracefully dispose them. However these receiver apps have their own connection.disconnect in them that attempts to send one final message to the cast device to close on its side... over a socket that is now closed. That would normally bubble up an exception that my catch would handle, but because this error happens all the way down in the socket connection, it instead raises an error event.
Normally, the overall client error handler would catch this, and this is what normally causes a disconnect/reconnect to keep connections alive. The trick I think here is that I only handle ONE error and then detach said event to avoid the event handler memory leak inherent to node.js's... design. But when the FIRST error results in a SECOND error in the Receiver's disconnect, there's now nothing handling that second error, and it bubbles up and crashes node-red.
I have an idea on how to handle this, but I don't really have a good way to TEST it. I'm gonna play around a bit tonight and see if I can reproduce this by starting a session and then pulling the plug on the cast device for 15 seconds (heartbeat timeout). Basically I'm looking at attaching a second error handler that just swallows these secondary errors (essentially an event based empty catch block).
But I need a reproduction so I'm gonna have to play a bit. Stay tuned.
Well, Im still unable to reproduce with an active cast to a Google Home and then pulling the power plug... it eventually times out and then goes through its normal connection loop.
What device are you casting to? Is it a group? Are you using mDNS discovery or a direct to IP/port cast? What application is running when this happens, or WAS running?
I also just pushed to master here a new version of castv2-sender.js... I haven't played with it too much yet, but it adds a generic error handler that hopefully will catch when this happens and write it to the console, but without crashing node-red...
If you get a chance, if you can try that file (Just replace your node-red/node_modules/node-red-contrib-castv2/castv2-sender.js file with that, and then restart node-red and then see if you can still reproduce the same issue (A full node-red restart), I'm curious if thats enough to avoid this or not.
Thank you for a very thorough explanation. I have replaced the castv2-sender.js file for testing.
I have so far tested it with the following devices. Each one is being connected to with a static IP address/port and no group features. Mostly casting from Netflix or YouTube using Android.
- 3 x Chromecast (Gen 1, Gen 2 and Chromecast with Google TV) for status (playing/not playing)
- 2 x Google Home Mini (mp3 playback from URL via Node-Red)
I mostly cast to the Gen 2 or Chromecast with Google TV and it randomly happens with both. But again I haven't reliably been able to reproduce it. Didn't for example happen even once yesterday but multiple times the day before without any change in habits or network etc.
I'm kinda leaning towards it happening mostly after something has been casted/played, the Chromecast/speaker going idle/sleep and then casting something again after a while.
Cool, let me know if it makes a difference for you.
The cast devices are supposed to close the application if idle for more than some timeout. This node will display one of two status values based on whether it is (a) only CONNECTED to the target, or (b) has JOINED an active session (connected vs joined). When said app closes on the target, it should send a notification that causes this app to revert from a "joined" to just "connected". If the app times out on the target like you say, are you seeing that transition correctly?
I wouldn't think that would cause your bug, but it would be another data point.
For the record, I am NOT seeing these restarts on mine, and I use a mix of Google Home Mini, Google Home, Chromecast gen 2 and NVidia Shields. Hopefully this change will stop it from happening and I can release it into the wild.
I'd like to report that so far I haven't seen any crashes with the new patched version.
Had less than normal amount of casting activity so it could be just luck but I'll keep testing and report back. I included the Chromecast version information if needed.
Google Home Mini - 1.56.264660
Chromecast Gen 1 - 1.36.159268
Chromecast Gen 2 - 1.49.250946
Chromecast with Google TV - 1.52.253741
Awesome! How often were you seeing it before? If we waited a week and you didn't see it anymore, would that be sufficient enough time to draw conclusions?
I used to see it daily or at least almost daily. I'd imagine a week would be enough to see the result. I should have more time to test come weekend, so unless it crashed this could be considered as fixed.
So hows it going? Any crashes to report?
I apologize for not responding earlier, but I've been very busy and I didn't manage to test well until yesterday evening.
We did a testing session where we started/stopped casting on 4 different Chromecast's while also having a mp3 playing on interval. We tested for about two hours or so. So Chromecast's were allow to go idle and some with simple start/stop/start/stop.
No crashes to report during our testing or before. So it seems the patch you provided works.
Ok, I pushed 4.1.2 then. Go ahead and update, and I'll close this one out! If you have any other issues let me know.