Topic: MC 28 crashes when DLNA device disappears (Read 2207 times)

DJLegba · « **on:** October 12, 2021, 07:06:57 pm »

I have a gen 1 Muso Qb, which I like, but it has always had poor WiFi connectivity. It's 2.4GHz only, and it seldom shows a strong connection in the Google mesh test, even when other nearby devices do. Sometimes when the signal strength is weak the Muso will crash, and I'll have to cycle its power. This happens with Spotify as well as MC, so I know the Muso is the chief instigator here. However, if the Muso crashes when MC is the source, MC will also crash. This wasn't a big problem with MC 27, but it's been consistent with all versions of MC 28. I'm currently using 28.0.73, 64-bit. I have the crash dump and the log file if anyone is interested in looking into this.

markf2748 · « **Reply #1 on:** October 13, 2021, 01:56:50 pm »

FYI - I don't see MC 28.0.75 64-bit crash when I disconnect power to a playing Chromecast Audio dongle, which appears to MC as a DLNA zone (provided by BubbleUPnP). MC handles it gracefully with the error message popup shown below.

Wireshark detected a bunch of byebye packets on the MC server's UDP port at about the time of disconnect; they may have originated from BubbleUPnP(?). Also found M-SEARCH broadcast. Unfortunately MC Media Server's Activity Log does not display enough time resolution or packet information to make a 100% correlation with Wireshark, but I'm guessing those packets are the reason for graceful disconnect.

My MC log file contains lots of "Bye-bye" lines with plenty of detail at the disconnect time. For starters, you could do a text search on "Bye-bye" to see if your log file has any. Maybe something changed in MC28 with regard to needing or reading these, or it crashes if they're absent after loss of connectivity.

As a test or awkward work around, run BubbleUPnP on your MC server, then play to the Muso Qb's built-in Chromecast as a MC DLNA zone. Look to see if it works/disconnects any better with Bubble in the loop. I have verified that MC - BubbleUPnP - Chromecast Audio dongle is bit-perfect at 44.1 and 96 KHz, 16 and 24 bits (not gapless).

Note - on my dual band router, 2.4GHz band has 5-15dB higher signal strength than 5GHz band. The Chromecasts are installed on 2.4GHz, while the MC server is on 5GHz - no problem with that. So I don't think your Muso operating at 2.4GHz is a disadvantage, unless your 2.4GHz channels are crowded.

AndrewFG · « **Reply #2 on:** October 17, 2021, 06:07:54 am »

IMHO if Muso is actually *crashing*, then it probably won’t get as far as sending any bye-byes at all; so it’s hard to imagine how unsent bye-byes could cause MC to crash; or??

markf2748 · « **Reply #3 on:** October 17, 2021, 01:30:14 pm »

Quote from: AndrewFG on October 17, 2021, 06:07:54 am

IMHO if Muso is actually *crashing*, then it probably won’t get as far as sending any bye-byes at all; so it’s hard to imagine how unsent bye-byes could cause MC to crash; or??

I agree about sending the byebyes. But what happens when MC plays to a DLNA renderer, which is alive, tries to communicate with it or is in the middle of communications, and then finds without warning (no previous byebye messages) that it is actually no longer there? Does MC handle that gracefully or does it crash? I know nothing of MC's internals and have no way to test that for a "pure" DLNA renderer - maybe someone else can try it. I suppose another scenario would be that when Muso crashes, it sends partial/invalid packets and that in turn crashes MC.

In the case of MC playing to a Google Chromecast Audio dongle, which BubbleUPnP Server shims into looking like a DLNA renderer, I was flabbergasted that suddenly unplugging power to the CA resulted in a string of byebye message packets. As amazing as the original $35 CA is, I have a hard time believing the device itself could send those packets, hence my guess that BubbleUPnP Server is doing the magic and MC accommodates. While many JRiver people probably think of Chromecast/Bubble as something to be tolerated and best avoided, I have found recent Bubble versions to be remarkably robust. Whenever I encounter an issue with disappearing CA (DLNA), the problem is linked to MC about 95% of the time, not Bubble, as far as I can see. Therefore the suggestion for a test of putting Bubble in the OP's loop, just to see if it helps, since Muso claims to have Chromecast capability built-in. If it does help, then JRiver may have some more work to do.

Further thought: After all, isn't the whole point of the PnP protocal that it should be robust against sudden disconnects (except maybe when cache or other process activity is involved)? We see that all the time with many USB PnP devices. When I look at all CA packets, I find a Service:ConnectionManager packet. Maybe that Service is the source for CA byebye messages, and there is either no DLNA analog for Muso or Muso's version fails? OP could look for it with Wireshark or search for Muso packets in the MC log file. It could be that Muso is a bad (i.e. silent) network player with regard to unexpected DLNA disconnects, in which case JRiver would have to decide whether it wants to deal with such renderers. One partial indicator might be for OP to turn off Muso while it is playing normally, and see if that also crashes MC.

AndrewFG · « **Reply #4 on:** October 17, 2021, 04:09:56 pm »

Quote

I find a Service:ConnectionManager packet.

Aha. Can you be more specific about that? What is sending it, and to whom?

markf2748 · « **Reply #5 on:** October 17, 2021, 05:33:35 pm »

Quote from: AndrewFG on October 17, 2021, 04:09:56 pm

Aha. Can you be more specific about that? What is sending it, and to whom?

Every 15 minutes the BubbleUPnP Server broadcasts 16 SSDP NOTIFY * HTTP/1.1 packets (4 server packets, 6 Chromecast Family Room packets, and 6 Chromecast New packets) from the MC Server NUC on which it runs to the Destination Port 1900 of same NUC. It then repeats the sequence 2 times, for a total of 48 packets in a total time of less than 0.5 second. The 15 minute blast interval is a default, and can be adjusted as discussed in my post over on the Media Network Forum https://yabb.jriver.com/interact/index.php/topic,130828.msg907581.html#msg907581.

The attachments show packets captured by Wireshark, typical of those in the Chromecast groups, including the service:ConnectionManager which I previously mentioned. These advertise two of the three Chromecast services which are available to the controller (the third is service:AVTransport). There are also packets which advertise the devices.

The advertised lifetime of all the packet info is given by the line Cache-Control:max-age=1800 which is 30 minutes and is consistent with the recommended refresh rate of half the max-age, or 15 minutes as observed. Further details of the servers are unknown to me, but I assume they are available somewhere for use by programmers.

JimH · « **Reply #6 on:** October 17, 2021, 06:31:14 pm »

Port 1900 is just SSDP. Bubble is advertising itself. Normal. But 15 minutes seems like a long interval.

AndrewFG is the Last Word here.

DJLegba · « **Reply #7 on:** October 17, 2021, 08:08:20 pm »

The gen 1 Muso doesn't support Chromecast. I do have two CCA devices and have used them in the past with Bubble, but I don't really need to use them that way anymore. I would be willing to do some logging with Wireshark. However, I thought that someone from JRiver would be interested in seeing the crash dump file and log, as this is something that has happened before and continues to happen. Even if it's the Muso causing MC to crash, ideally MC should be able to handle bad behaviour by DLNA devices without crashing. The problem can't be triggered by unplugging the Muso - it seems to require a marginal WiFi connection.

Here's the end of the log file from the most recent crash:

168547611: 9812: Sharing Plugins: JRWebService::Process: Start
168547611: 9812: Sharing Plugins: JRWebService::Process: URL: /MCWS/v1/Playback/Info?Zone=10032&Token=2Kb7FzP5
168547611: 2948: General: TopLevelExceptionFilter: Unhandled exception -- program crashing
168547611: 2948: General: TopLevelExceptionFilter: Message: 275, wParam: 3, lParam: 0
168547611: 9812: Reader: CWinINetReader::Open: Start
168547611: 9812: Reader: CWinINetReader::Open: Opening http://192.168.86.26:8080/AVTransport/ctrl
168547612: 3968: Reader: CWinINetReader::Thread: Start
168547612: 3968: Reader: CWinINetReader::Thread: url: http://192.168.86.26:8080/AVTransport/ctrl
168547612: 3968: Reader: CWinINetReader::Connect: Start
168547612: 2948: General: RunProgram: Start
168547612: 2948: General: RunProgram: Filename: C:\Program Files\J River\Media Center 28\JRCrashHandler.exe / Parameters: JRCrashInfo4220
168547612: 2948: General: RunProgram: Performing ShellExecute...
168547612: 3968: Reader: CWinINetReader::Connect: Finish (0 ms)
168547612: 3968: Reader: CWinINetReader::DownloadFromHTTPURL: Start
168547612: 3968: Reader: CWinINetReader::DownloadFromHTTPURL: HttpOpenRequest successful
168547663: 3968: Reader: CWinINetReader::DownloadFromHTTPURL: HttpSendRequest successful
168547664: 3968: Reader: CWinINetReader::DownloadFromHTTPURL: Success
168547664: 3968: Reader: CWinINetReader::DownloadFromHTTPURL: Finish (51 ms)
168547664: 3968: Reader: CWinINetReader::Thread: Finish (51 ms)
168547664: 9812: Reader: CWinINetReader::Open: Finish (52 ms)
168547674: 9812: Reader: CWinINetReader::Close: Start
168547675: 9812: Reader: CWinINetReader::Close: Finish (0 ms)
168547675: 9812: Sharing Plugins: JRWebService::Process: Finish (64 ms)
168547676: 9812: Sharing Plugins: VHTTPMessage::Write: Wrote 1183 bytes
168547734: 9812: Sharing Plugins: CHTTPRequestMessage::ReadPreamble: Failed to read Method
168547734: 9812: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (124 ms)
168547734: 9812: General: CReferenceCountedSocket::Close: SOCKET_DEBUG: closesocket() closing 2316
168547853: 2948: General: RunProgram: Running process...
168547853: 2948: General: RunProgram: Waiting for completion
0000004: 1104: General: JRCrashHandlerApp::Run: Start
0000004: 1104: General: JRCrashHandlerApp::Run: Opening Shared Memory: JRCrashInfo4220
0000004: 1104: General: JRCrashHandlerApp::CreateMiniDump: Start
0000010: 1104: General: JRCrashHandlerApp::CreateMiniDump: Trying to set dump privileges
0000012: 1104: General: JRCrashHandlerApp::CreateMiniDump: Creating dump output file at C:\Users\Mike\AppData\Roaming\J River\Media Center 28\Crash.dmp
168549074: 3648: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Start
168549074: 3648: Sharing Plugins: CHTTPListenerWorker::HandleRequest: TCP: 192.168.86.246: GET: http://192.168.86.42:52200/MCWS/v1/Playback/Info?Zone=10032&Token=2Kb7FzP5
168549076: 3648: Sharing Plugins: JRWebService::Process: Start
168549076: 3648: Sharing Plugins: JRWebService::Process: URL: /MCWS/v1/Playback/Info?Zone=10032&Token=2Kb7FzP5
168549076: 3648: Reader: CWinINetReader::Open: Start
168549076: 3648: Reader: CWinINetReader::Open: Opening http://192.168.86.26:8080/AVTransport/ctrl
168549076: 4940: Reader: CWinINetReader::Thread: Start
168549077: 4940: Reader: CWinINetReader::Thread: url: http://192.168.86.26:8080/AVTransport/ctrl
168549077: 4940: Reader: CWinINetReader::Connect: Start
0001102: 1104: General: JRCrashHandlerApp::CreateMiniDump: Finish (result: 1) (1097 ms)
168549077: 4940: Reader: CWinINetReader::Connect: Finish (0 ms)
0001102: 1104: General: JRCrashHandlerApp::Run: Finish (1098 ms)
168549077: 4940: Reader: CWinINetReader::DownloadFromHTTPURL: Start
0001102: 1104: General: JRCrashHandlerApp::ExitInstance: Finishing
168549077: 4940: Reader: CWinINetReader::DownloadFromHTTPURL: HttpOpenRequest successful
168549088: 2948: General: RunProgram: Finished
168549088: 2948: General: RunProgram: Done waiting
168549088: 2948: General: RunProgram: Finish (1475 ms)
168549135: 4940: Reader: CWinINetReader::DownloadFromHTTPURL: HttpSendRequest successful
168549135: 4940: Reader: CWinINetReader::DownloadFromHTTPURL: Success
168549135: 4940: Reader: CWinINetReader::DownloadFromHTTPURL: Finish (58 ms)
168549135: 4940: Reader: CWinINetReader::Thread: Finish (58 ms)
168549136: 3648: Reader: CWinINetReader::Open: Finish (59 ms)
168549150: 3648: Reader: CWinINetReader::Close: Start
168549151: 3648: Reader: CWinINetReader::Close: Finish (0 ms)
168549152: 3648: Sharing Plugins: JRWebService::Process: Finish (76 ms)
168549152: 3648: Sharing Plugins: VHTTPMessage::Write: Wrote 1183 bytes
168549305: 3648: Sharing Plugins: CHTTPRequestMessage::ReadPreamble: Failed to read Method
168549306: 3648: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (231 ms)
168549306: 3648: General: CReferenceCountedSocket::Close: SOCKET_DEBUG: closesocket() closing 3644
168551695: 7668: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Start
168551695: 7668: Sharing Plugins: CHTTPListenerWorker::HandleRequest: TCP: 192.168.86.246: GET: http://192.168.86.42:52200/MCWS/v1/Playback/Info?Zone=10032&Token=2Kb7FzP5
168551695: 7116: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Start
168551695: 7116: Sharing Plugins: VHTTPMessage::ParseBody: Start
168551696: 1072: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Start
168551696: 7116: Sharing Plugins: VHTTPMessage::ParseBody: Reading 392 bytes from message body
168551696: 7116: Sharing Plugins: VHTTPMessage::ParseBody: Finish (0 ms)
168551696: 9232: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Start
168551696: 7116: Sharing Plugins: CHTTPListenerWorker::HandleRequest: TCP: 192.168.86.26: NOTIFY: http://192.168.86.42:52104/eventSub
168551696: 1072: Sharing Plugins: CHTTPListenerWorker::HandleRequest: TCP: 192.168.86.246: GET: http://192.168.86.42:52200/MCWS/v1/Playback/Info?Zone=10032&Token=2Kb7FzP5
168551696: 9232: Sharing Plugins: CHTTPListenerWorker::HandleRequest: TCP: 192.168.86.246: GET: http://192.168.86.42:52200/MCWS/v1/Playback/Info?Zone=10032&Token=2Kb7FzP5
168551696: 7116: Sharing Plugins: VHTTPMessage::Write: Wrote 0 bytes
168551696: 7116: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (1 ms)
168551696: 7116: General: CReferenceCountedSocket::Close: SOCKET_DEBUG: closesocket() closing 3588
168551697: 7668: Sharing Plugins: JRWebService::Process: Start
168551698: 7668: Sharing Plugins: JRWebService::Process: URL: /MCWS/v1/Playback/Info?Zone=10032&Token=2Kb7FzP5
168551698: 1072: Sharing Plugins: JRWebService::Process: Start
168551698: 1072: Sharing Plugins: JRWebService::Process: URL: /MCWS/v1/Playback/Info?Zone=10032&Token=2Kb7FzP5
168551698: 7668: Reader: CWinINetReader::Open: Start
168551698: 7668: Reader: CWinINetReader::Open: Opening http://192.168.86.26:8080/AVTransport/ctrl
168551699: 4844: Reader: CWinINetReader::Thread: Start
168551699: 4844: Reader: CWinINetReader::Thread: url: http://192.168.86.26:8080/AVTransport/ctrl
168551699: 4844: Reader: CWinINetReader::Connect: Start
168551699: 9232: Sharing Plugins: JRWebService::Process: Start
168551699: 9232: Sharing Plugins: JRWebService::Process: URL: /MCWS/v1/Playback/Info?Zone=10032&Token=2Kb7FzP5
168551699: 4844: Reader: CWinINetReader::Connect: Finish (0 ms)
168551699: 4844: Reader: CWinINetReader::DownloadFromHTTPURL: Start
168551699: 4844: Reader: CWinINetReader::DownloadFromHTTPURL: HttpOpenRequest successful

markf2748 · « **Reply #8 on:** October 17, 2021, 10:53:48 pm »

I'm not from JRiver, but one thing that sticks out in your file are six references to http://192.168.86.26:8080/AVTransport/ctrl I can't tell for certain whether all calls to that address are successful.

Long shot, but since you are playing a zone, have you tried running with AVTransport disabled?
Right click on zone > DLNA Controller Options > [checkmark] Ignore Transport Events (use polling mode)

Try some or all of the other DLNA Controller Options?

Is the last line always the same in every log file after a crash, or is it more random?
If more random, then it might point towards an issue with the way MC handles low signals/loss of signals generally, rather than a specific section of code indicated in the log.

DJLegba · « **Reply #9 on:** October 18, 2021, 07:55:02 am »

^
Thanks for looking at the issue and offering some suggestions. The Whitebear DMRA says the Muso's DNLA support is good:

AVT:GetDeviceCapabilities action   Supported
AVT:GetMediaInfo action   Supported
AVT:GetPositionInfo action   Supported
AVT:GetTransportInfo action   Supported
AVT:GetTransportSettings action   Supported
AVT:SetNextAVTransportURI (gapless play)   Supported
AVT:SyncPlay (synchronous play)   NOT Supported

As a user I could tweak settings to see if I can prevent the crash, but the last time it happened my son said "why don't you just stop using JRiver?" So I thought a JRiver developer might be interested in figuring out why MC crashes and what can be done about it in MC.

bob · « **Reply #10 on:** October 21, 2021, 08:50:07 am »

Please email the crash dump to bob (at) jriver (dot) com.
Thanks

jmone · « **Reply #11 on:** October 21, 2021, 04:24:33 pm »

Hey Bob, I've posted in the Beta Forum a log for this issue as well - https://yabb.jriver.com/interact/index.php/topic,130529.0.html

bob · « **Reply #12 on:** October 21, 2021, 07:21:26 pm »

Quote from: jmone on October 21, 2021, 04:24:33 pm

Hey Bob, I've posted in the Beta Forum a log for this issue as well - https://yabb.jriver.com/interact/index.php/topic,130529.0.html

I'll look at that but the crash dump if not corrupted is the most useful.

jmone · « **Reply #13 on:** October 24, 2021, 04:27:21 pm »

Unfortunately the only Windows Crash Dump I have is from last year (which I've now deleted). I was playing with a going bad amp for the outside sound system which has DLNA render feeding it (so was powering it on/off while playing content from MC) and my entire PC was Blue Screening with a Watchdog error but no dump file was being created.

bob · « **Reply #14 on:** October 25, 2021, 04:58:08 pm »

It looks like it's a complex issue related to making the reader available to the audio path when transcoding to a DLNA renderer. We are going to disable that until we figure out a solution.

jmone · « **Reply #15 on:** October 25, 2021, 07:19:26 pm »

Thanks bob, let me know if you need any testing.

jack wallstreet · « **Reply #16 on:** November 01, 2021, 05:31:41 pm »

I am having this problem with 0.80 every time my Sonos Move speakers do an auto shutdown (music not playing). FYI

bob · « **Reply #17 on:** November 01, 2021, 05:51:42 pm »

Quote from: jack wallstreet on November 01, 2021, 05:31:41 pm

I am having this problem with 0.80 every time my Sonos Move speakers do an auto shutdown (music not playing). FYI

Please send a crash dump. It's much easier to track these down with that.

jack wallstreet · « **Reply #18 on:** November 01, 2021, 07:04:26 pm »

Here is the log file (I hope I did this correctly). Started the log file when the two Sonos Moves where active. Then I stopped the music (play stop) and waited. Eventually MC was no longer loaded - (40 min???) - it seems to have closed itself or crashed. I then restarted MC and sent the attached log. I did not get my normal "MC crashed presviously" notice on restart. Maybe that happens only when in addition, the computer has gone to sleep. I'll have to check that out. Hopefully this helps.

bob · « **Reply #19 on:** November 01, 2021, 08:55:03 pm »

Quote from: jack wallstreet on November 01, 2021, 07:04:26 pm

Here is the log file (I hope I did this correctly). Started the log file when the two Sonos Moves where active. Then I stopped the music (play stop) and waited. Eventually MC was no longer loaded - (40 min???) - it seems to have closed itself or crashed. I then restarted MC and sent the attached log. I did not get my normal "MC crashed presviously" notice on restart. Maybe that happens only when in addition, the computer has gone to sleep. I'll have to check that out. Hopefully this helps.

Do you also have the crash dump?
On windows after a crash in Help->Logging if you do Report Problem it should include a crash dump.

INTERACT FORUM

Author Topic: MC 28 crashes when DLNA device disappears (Read 2207 times)