Print

Please login or register.
1 Hour 1 Day 1 Week 1 Month Forever
Login with username, password and session length

[RalphBrooks]

Great feedback, thanks.
A few quick responses:
- No, I do not hear a pop on the start of songs that do not complete
- Yes, I did find the Laptop DLNA Audio output was set to MP3, but I didn't write down if it was before or after the one failing cycle I captures an Ethernet log, clearly it was after.
 I have it set to the same as the NUC now, "original format" so I will do more testing today to see if that might be the factor which caused Laptop to always pass now. 
- I'll make a crossover network cable today and retest without the Network box (yes I have the parts, tools and skill), just didn't have a need for one before so no spare one laying around like I do other LAN cables.
- I will also look at reconfiguring to 100MB vs 1GB network speed and retesting.
- Also not against obtaining a USB network card to eliminate NIC differences between Laptop and NIUC.

I'll respond later today after I get back (received a critical call so I'm off to help a friend with problems on her computer)

 

[zybex]

received a critical call so I'm off to help a friend with problems on her computer

I approve of your priorities 

[RoderickGI]

It's good to have a programmer on the team! Nice summary again Zybex.

You can pull the actual files out of the traces? I must learn how to use Wireshark better. I don't have the detailed networking knowledge really, or programming skills. 

I knew, and said, those RESETs were my major concern! 

[AndrewFG]

^
Cool analysis zybex!

Concerning the RESETs that you are observing: Can you tell from the Wireshark timestamps whether the RESET occurs before or after the time at which the respective part of the track would have been played? Maybe it is simply a bandwidth throttling issue where the renderer runs out of downloaded bytes to actually play? That would probably cause the renderer to reset and retry...

[RalphBrooks]

Based on latest feedback I’ve spend the last few days performing another series of tests

Summary:
No impact/improvement by specifying LAN speed on the NUC at 100MB, nor did replacing the Ethernet Switch box with an RJ-45 cross-over Lan cable, NUC still fails/hangs.  Also tried swapping out LAN cables on NUC and Primare, but again no effect.  Not yet obtained/tried USB Ethernet adapter.  However, additional testing using my Laptop proved more interesting, but also frustrating as odd pass/fail behavior was not repeatable. 

100M vs 1G LAN speed comparison test:
Reconfigured the NIC in the NUC to be 100MB speed instead of enabling 1Gigb support and looped on a song/file shown to repeatedly fail.
Note: The Priamare BD32 MKII (as well as the OPPO BDP105) only support 10/100 LAN, so the 1GB capable NIC in the NUC Sever has to negotiate down 100Mb speed any Ethernet interaction anyway
-  Test hardware NUC & Primare
-  Album: Modified 7-walkers (7_Walker_test_3)
    *  Track 12 off this same album I’ve been using (7-Walkers) that O  (track 12)
    *  Same song used 10 times with different track number and file name assigned.
    *  Metadata removed
-  Files stored locally on NUC SSD, no NAS involved
-  Selected Network configurations disabled in device manager (per prior responses)
-  On the NUC Entered control panel and device manager/network adapters/Realtec PCIe GBE Family Controller/advanced tab/Link speed & duplex/ changed setting from Auto Negotiation to 100Mbps full duplex
-  Rebooted NUC after setting change with system connected to home network
-  Then disconnected from the home network
Result: Failed/hung consistently on first or second song (tested 5 time to confirm), so forcing Ethernet speed to 100Mb showed no change in failures.

Remove Ethernet Switch Box from the configuration:
Built and tested with RJ-45 crossover cable between NUC and Primare player instead of going thru the 1Gb Ethernet switch.
-  Test hardware NUC & Primare
-  Album: Modified 7-walkers (7_Walker_test_3)
    *  Track 12 off this same album I’ve been using (7-Walkers) that O  (track 12)
    *  Same song used 10 times with different track number and file name assigned.
    *  Metadata removed
-  Files stored locally on NUC SSD, no NAS involved
-  Selected Network configurations disabled in device manager (per prior responses)
-  After powering all unit on connected to home network I replaced Ethernet connections between both NUC and Primare to the Ethernet Switch Box with a single direct RJ-45 crossover cable between the NUC and Primare
- Also test with NIC speed configured using both 100Mb as well as Auto Negotiation in device manager
Result: NUC failed/hung consistently on first or second song (tested 5 time to confirm), so the Switch box does not appear to be a contributing factor in failures

Comparison Testing between Laptop and NUC:
Before starting this sequence of tests I first verified that the DLNA settings in MC on both the Laptop and NUC are configured the same.
Since the Laptop was consistently passing and I found a consistently failing test album played on the NUC my initial plan was to capture trace logs of both devices playing the same album/songs in passing cycles on the Laptop and then failing cycle on the NUC. 

To do this I decided to use the same test album I have been using 7_Walker_test_3 (same song loaded 10 times), which consistently fails on the NUC and the “same” 7_Walker_test_3 test album loaded on the Laptop consistently passes on the Laptop.   However, I noticed when playing this test album on my laptop there had to be some extra metadata loaded on the laptop local version compared to the same test album loaded on the NUC local drive.  I found that my Laptop had the Library Import option box checked to Analyze audio on new files so when I imported the album it added the additional metadata.  Both versions had Artwork removed and most of the other meta-data, but I still wanted to do an apple-to-apple comparison of the exact same test album.  So I worked on getting the exact same files on both devices.

Because the two test albums had the same file/artist/album artist names I could not just copy/import the version from the NUC local drive onto my laptop local drive without MC  displaying duplicate songs making it difficult to select what song to play.  The next few steps I took resulted in some odd pass/fail behavior, but it might provide additional pointers to the root cause of my issue.

I copied the 7_Walker_test_3 test album from the NUC local drive and installed it on the Laptop local drive under a difference directory name so as not to disturb/edit the actual files.  Since it has the same meta-data names I deleted the current 7_Walker_test_3 from the Laptop MC library (kept the files) and then imported the 7_Walker_test_3 files I copied from the NUC.  Retested on the Laptop
Result:  They failed, consistently on the first or second song on multiple test runs.  That was a new behavior I have not been able to reproduce consistently on the Laptop until now. Since my Laptop was back in my office and on the home network I did not capture an Ethernet trace of this failure 

However, I could now envision a possible way to capture Ethernet Trace logs of both a failing and passing cycle on a single device (Laptop) using the same song.  I had the newly failing test album already imported, but now I needed to create and import the passing test album which I had previously removed from MC.  So I created a copy of the original folder containing the 7_Walker_test_3 on the Laptop local drive and edited the meta-data to add an e at the end (NUC 7_Walker_test_3_e).  I then imported and tested this slightly modified test album. 
Test Result:  Test album Walker_test_3_e passed as expected, but I went back and retested  the 7_Walker_test_3 that I had copied from the Laptop (and this is the odd behavior) it would no longer fail    

Hmmm… now what to do.
Odd, that importing the additional test album made the failing album start passing on the Laptop.
Next I thought I’d try the same kind of experiment using the NUC.

Here is what I tried: I made a copy of album 7_Walker_test_3 off the NUC (containing less meta-data) and edited Artist and Album_Artist, named it 7_Walker_test_4 and put it in a new folder on the NUC local drive also called 7_Walker_test_4. I then imported this into MC on the NUC.  I then tested 7_Walker_test_4
Result: NO FAILURES.  This was great, as it was the first time I’ve seen consistently passes on this song with the NUC as server.
I captured an Ethernet trace log showing the first four songs of 7_Walker_test_4 successfully playing (I stopped shortly after the forth song started).
Log 7: https://drive.google.com/file/d/1sKyALvMCb3ykfhroFQxoxrM7NUrIWy_q/view?usp=sharing

Next I retesting test album 7_Walker_test_3 on the NUC local drive in the hope I could now get a side by side comparison on a passing and failing cycle on the same server device with basically the same song, very small difference in meta-data. 
Result:  The original 7_Walker_test_3 of which I did not touch and which had consistently failed on the first or second play of a song….NO LONGER FAILS.  I tested this multiple times.  Now this was odd. 

Next I rebooted the NUC/MC and retested 7_Walker_test_3 again.,
Result:  Now it was back to failing on the first or second song, again!  I tested this multiple times.  Log 8 shows it failing at end of first song
Log 8: https://drive.google.com/file/d/1GvsG0FYf8MuejOnIEm5xqwDVczhYhQx4/view?usp=sharing

We can compare Log 7 which captured passes cycles against Log 8 which captured fail/hung at the first song.
Question: Do these logs show any significant difference in behavior in terms of things like resets being sent?
Question: How might rebooting the NUC and reloading all the software cause this kind of behavior in this case.  Memory getting reloaded differently?

I then retested test album 7_Walker_test_4 again.
Result: I was now failing as well on the first or second song.

Next, I wondered if I could back out the 7_Walker_test_4 album addition, reboot and add it back it again and see if 7_Walker_test_3 album will start passing again on the NUC.
Result:  It still fail.  This means I could not reproduce this odd sequence of events observed on the NUC 

Given this odd (and unrepeatable) behavior using the NUC I decided to go back to testing with the Laptop again:
I first retested two of the test albums now residing on the Laptop local drive
-  7_Walkers_test_3 - The initial file (containing MC waveform analysis in metadata)
-  7_Walkers_test_4 - Same 10 audio files, but I copied the 7_Walkers_test_3 file off the NUC which has the waveform analysis in metadata removed) and renames the metadata/file name as 7_Walkers_test_4
Result: Both albums still passing (which is where I last left it) so I captured an Ethernet event log of a passing cycle of the first 4 songs of 7_Walkers_test_4 using Laptop as server.
Log 9:  https://drive.google.com/file/d/1etrhsnP2r_goiDc2EEEZvltVBLe1Ew_1/view?usp=sharing

I created yet another test album 7_Walkers_test _5, an exact copy of 7_Walkers_test _4 and imported to see if loading another test album would will cause it to start failings so I could do a side by side Ethernet log comparison on the Laptop.
Result:  No change, everything still passing (I did capture a log, but it’s all passing data playing the first four songs)
Log 10:  https://drive.google.com/file/d/1WN96LiLrzn4WKzqvtcqWzY-cLcFv_I6V/view?usp=sharing

So what to try next other than try a USB Ethernet card.  Run memory test on memory card in NUC?  Replace memory card?  I've seen/logged failures with the Laptop as server, just not as repeatable as it is with the NUC. 

[wer]

You've put a lot of time in on this.  Get the USB ethernet adapter and test with that. Take a break until it arrives.

I don't like the bad RAM idea.  Results are too consistently tied to certain files.

In future I would like to see you stick to testing with the exact same files on both systems.  Copy them from one machine to another and md5 hash them to ensure they remain unchanged.  There is definitely a data problem involved, so it is essential the files not change.  Make sure neither MC is writing to those tags, and periodically validate the md5 hashes. We don't want shifting data.

One thing that might be interesting: if there's a utility that can download and save to disk a DLNA served file (Andrew?), download and save the same file 50 times, md5 hash all of them, and see if all the files are identical to the original.

As an aside, if we get nothing else out of this thread, I'd like Rod to publicly acknowledge that DLNA is a pain in the bollocks and that I show great wisdom in advising people that they should avoid it whenever humanly possible.

[RoderickGI]

Result:  They failed, consistently on the first or second song on multiple test runs.  That was a new behavior I have not been able to reproduce consistently on the Laptop until now. Since my Laptop was back in my office and on the home network I did not capture an Ethernet trace of this failure 

I suspect that was just an anomaly with the test procedure. MC on the Laptop or the Primare might have been in a state which caused the failure due to the earlier tests. If you had rebooted the devices between this and the earlier test it may not have happened. As Wer says, probably not bad RAM, but possibly memory being used in a way that caused some issue with software or network operation. It isn't repeatable anyway, so don't worry about it.

As Wer says, use exactly the same files if comparing the laptop to the NUC, or just test on the NUC and see if we can find the issue.

But taking a break and testing with a USB network device sounds like a good idea. 

I haven't looked at these latest traces yet. There may be something in them.

Ah, I just read further down your post. A reboot of the NUC saw failures return. It looks like a comparison of Logs 7 & 8 might yield some information.

[zybex]

(haven't read above yet)

Andrew,
- the 4 cancelled transfers take about 0.6 seconds total
- Playback starts about 1.4 seconds after into 5th transfer (so, about 2 seconds after MC issues the Play command)
- When playback starts, 4.8MB have already been transferred (about 50 seconds of FLAC audio)
- after this the player throttles the transfer speed by adjusting TCP Window Size. MC polls for position every 5 seconds
- file transfer ends when playback is around 2:08 (of 3:04)
- playback ends, but reports position=3:03 of 3:04 continuously, so MC doesn't advance.

If MC issued a GetTransportInfo, it would probably get a STOPPED... but it doesn't do that.

Attachment shows the sequence with relevant packets highlighted. I added a Comment column.

[zybex]

Ralph, in my view the random behavior points to a problem in the Player, not the NUC or MC (though MC detection of end-of-file could be improved).
When I mentioned RAM problems, I was talking about the memory in the Player, not the NUC.

The facts are:
- the Player is the one cancelling transfers mid-way. I compared the captured partial transfers to the full file and there are no differences - so, no data corruption on the NUC side. If the Player is aborting the transfer it's because it detects some internal error, decoding error, etc, hence I was thinking of data corruption *in the player's memory*.
- the Player is the one showing random behavior. Sometimes, for the same song, it reports the end position correctly while other times it stops at -1s. MC is just responding to that, waiting for EOF before playing next song.
- the failure has a clear root cause: the Player ends a song but reports that there's still 1 second left. MC is just reacting to that.
- MC already has mitigation options that work for this player, according to you. They likely use a different method of tracking current state/position, which seems to be needed for your Player.

If you want to rule out MC, you could setup another DLNA server and play the same songs with it - NOTE HOWEVER that a different DLNA server may very well detect that the player is now stopped at -1s and advance to the next song anyway... so not really easy to test/compare. In fact, this is likely to be what MC does with one of those Polling/Event mitigation options, which you said actually solve this problem for you.

Edit: I realize you have 2 similar units exhibiting the same behavior, so an hardware failure in both is unlikely. So the most likely culprit in this case would be a Firmware bug, causing that misreporting of the position under certain conditions. Most likely a rounding error, 3:03.765 => 3:03

Edit 2: Do these units have SNMP capabilities per chance? If so you could use it to debug their internal state and see eventual error messages.

[zybex]

Regarding Log7 above, which had no failures: on this one you can see the EVENT/NOTIFY system was enabled, so it worked because of that. I can see MC subscribing to events, and at the same time polling for the current position. When it reaches 3:03 (of 3:04), the Player sends a NOTIFY to tell MC that playing is now STOPPED - in response to this, MC advances to the next song. Playback never reaches 3:04, it's just the EVENT that makes it work.

On the other logs with failures there are no Events, so it looks like you overlooked this config option on this one, or MC didn't apply it until after restart.
Since the option is called "Ignore Transport Events (Use Polling Mode)", it would seem that it needs to be OFF for this Player to work, using Events. Perhaps the option is misnamed or its logic is reversed?

EDIT: Same for log 9 and 10, it's using EVENT/NOTIFY so it's working.

At this point, I feel you should just leave Events enabled and don't waste more time. Player requires it, MC does it, and it all works...

[RalphBrooks]

Regarding Log7 above, which had no failures: on this one you can see the EVENT/NOTIFY system was enabled, so it worked because of that. I can see MC subscribing to events, and at the same time polling for the current position. When it reaches 3:03 (of 3:04), the Player sends a NOTIFY to tell MC that playing is now STOPPED - in response to this, MC advances to the next song. Playback never reaches 3:04, it's just the EVENT that makes it work.

On the other logs with failures there are no Events, so it looks like you overlooked this config option on this one, or MC didn't apply it until after restart.
Since the option is called "Ignore Transport Events (Use Polling Mode)", it would seem that it needs to be OFF for this Player to work, using Events. Perhaps the option is misnamed or its logic is reversed?

EDIT: Same for log 9 and 10, it's using EVENT/NOTIFY so it's working.

At this point, I feel you should just leave Events enabled and don't waste more time. Player requires it, MC does it, and it all works...

Very interesting, but also very confusing as I checked that setting each time I reboot or start a new test and I'm SURE the BR32MK2/DLNA Controller Options/Ignore Transport Events (use polling mode) options is NOT set on either the NUC nor the Laptop MC options.  How it's in that mode without setting that option I do not understand.  Since it appears to be getting into that mode without me manually setting it that would certainly explain my test results and why for example I can no longer get the Laptop to fail at all where before it would fail, just not not as frequently as when using the NUC.  For example, I ran it all night on a playlist and no failures and I just confirmed (again) that setting is not checked.  Maybe MC has an issue where once that option is set it is not unset without some difference sequence of events other than unsetting that option.

In any event I headed down this debug path and put the time and energy into looking for more data out of concern there maybe some other issue at fault other than what appears to be yet another example of a broken DLNA implementation, in this case on the Primare/Oppo designs.  Alas I will now simply selected the polling configuration option and move on to other challenges.

And while I agree DLNA can be a pain in the A-- , its still a very useful means to leverage existing player hardware other than going and buying additional (and expensive) DAC hardware.  This is especially true in my case where I replaced my OPPO BDP-105 with the Primeare BD32 MKII because of it's exceptional audio quality (nothing better in a universal player) and it supports multi-channel (I have a very nice 5.1 channel entertainment system).  A comparable multi-channel DAC replacement for my Primare would be the ExaSound E38 at at price of around $4K (I paid $6K for my Primare in 2015).  So I'd like to keep using DLNA and my Primare as long as I can.

I  thank you all for your exceptional support (few sites like the JR Interact forum), it's been immensely educational and a pleasure.  Makes me "almost" miss my life as a PC hardware design engineer at Intel.  But I'm enjoying retirement more

[bob]

The controller options changes SHOULD take effect after MC is in stop mode (with gapless transitions set you may need to hit stop twice).
Always safer for testing to restart MC though and especially when disabling / enabling events.

MC increases the frequency of calls for position in the last 5 seconds of the track.
It's possible when eventing is disabled we might need to make more transport state calls in there for buggy devices, will check into that.

[zybex]

I'm SURE the BR32MK2/DLNA Controller Options/Ignore Transport Events (use polling mode) options is NOT set on either the NUC nor the Laptop MC options.

Well.. from the name of this option, I would say it needs to be SET to work with polling only, and NOT SET to work with Events. So by doing that, you made sure events were enabled (or the option is misbehaving/not taking effect immediately/badly named)

Makes me "almost" miss my life as a PC hardware design engineer at Intel.  But I'm enjoying retirement more

So it was you! See the mess you left behind? It's all falling apart now, they can't handle it without you!

Happy retirement

[dtc]

  Makes me "almost" miss my life as a PC hardware design engineer at Intel.  But I'm enjoying retirement more

Not sure how long you were there or exactly what group you were in, but I was the lead workstation analysis at IDC when Intel based systems starting taking over the workstation market from Unix based systems. I worked with many people in the Intel PC group in those days, including Dileep Bandarkar, who was an old friend from Digital days. Fun times.

[AndrewFG]

Look, I also have an Oppo 105, so do you want to send me the troublesome files in your playlist, so I can test them on my player?

[RoderickGI]

Lovely summary again Zybex.

Some confusion over the "Ignore Transport Events (Use Polling Mode)" setting. I think it was sorted over multiple posts, but...

When it is ticked, MC doesn't use Event style transport control, but uses Polling Mode, and that does indeed work for Ralph. But using Transport Events is better. I think it is required for proper Gapless? Not sure. Bob?
When it is not ticked, MC uses Event style transport control. This is what Ralph has been testing.

It sounds like in logs 7, 9, and 10, Event style control was working. But in log 8 it wasn't. In all cases it was turned on, and should have been working.



I saw Event Subscriptions in traces where playback stalled, but I didn't check for each track. Maybe there is no Event Subscription, or no matching NOTIFY for the failed tracks.

There are still some mysteries:
1. Why does the Primare RESET the transfer? There is no obvious reason in the trace. It could just be a bug in the Primare firmware, but...
2. Why does playback work on the laptop, but not on the NUC, for basically "the same" files, and fairly consistently?

The reason for 1. could be some sort of packet flood control, where the Primare gets overwhelmed and so says "start again". That would point to the NIC or OS settings on the NUC versus the Laptop. Hence Wer's suggestion, I suspect, to test with a USB NIC. But the transfer rate seems to be only about 3.888 Mbps, so that shouldn't be an issue.


Also @Bob, this change looks like it should address the issue of the Renderer not issuing an Event/NOTIFY to report completion of a track when Transport Events is being used. Is that code still there and working?

24.0.36 (6/20/2018)
12. Changed: DLNA, Add a code that will do a manual transport state update if we look frozen at the end of a track (missed an event..)



This has been a good thread, because there have been lots of DLNA threads that never quite get to the bottom of why something wasn't quite working. If there was a cause found, maybe the problems other people experience could be eliminated.

[Scobie]

I think it is required for proper Gapless?

No I don't think it has any effect on gapless, that is more the SetNext option. I believe it is simply more efficient - less traffic, more responsive etc - not to have to poll for updates.

I've got a renderer that needs Ignore Transport Event ticked, but plays gapless no problem; so I can't say having this set is an issue at all.

[RoderickGI]

Regarding Log7 above, which had no failures: on this one you can see the EVENT/NOTIFY system was enabled, so it worked because of that. I can see MC subscribing to events, and at the same time polling for the current position. When it reaches 3:03 (of 3:04), the Player sends a NOTIFY to tell MC that playing is now STOPPED - in response to this, MC advances to the next song. Playback never reaches 3:04, it's just the EVENT that makes it work.

In this Log7 where playback worked, at the end of the first track I can see the frame:
20768   190.557669   192.168.1.246   192.168.1.109   HTTP/XML   52102   f4:4d:30:6c:b0:a1   58123   1000   NOTIFY /eventSub HTTP/1.1

But I can't really relate that to the Renderer telling MC that playback has finished for the track. It does get a response that the connection is closed, and maybe that is all that is required.
20771   190.561360   192.168.1.109   192.168.1.246   HTTP   58123   00:22:de:8c:ce:10   52102   54   HTTP/1.1 200 OK

I just don't know enough about DLNA EVENT conversations to know if that is sufficient, or the appropriate response. However, it is after that frame that MC starts asking for Transport Info, and gets the "STOPPED" response, twice, before MC sets the next Transport URI in frame:
20788   190.683092   192.168.1.109   192.168.1.246   HTTP/XML   2870   00:22:de:8c:ce:10   50704   386   POST /control/AVTransport HTTP/1.1



There are other EVENT Subscription frames that just appear in the middle of nowhere:
25437   191.560212   192.168.1.109   192.168.1.246   HTTP   58131   00:22:de:8c:ce:10   52102   54   HTTP/1.1 200 OK
and also close the connection.

There are also a bunch of RESETs in Log7, but playback still worked.

There is a very late response to a GET, and the response is what MC usually sends for a HEAD frame, "Partial Content".
26683   191.928707   192.168.1.246   192.168.1.109   HTTP   52100   f4:4d:30:6c:b0:a1   45220   191   GET /Music/F590337.flac?Reader=10 HTTP/1.1
41179   321.235456   192.168.1.109   192.168.1.246   HTTP   45220   00:22:de:8c:ce:10   52100   413   HTTP/1.1 206 Partial Content  (audio/x-flac)
but playback continues without a RESET.

Another EVENT in the middle of nowhere:
41373   336.166634   192.168.1.246   192.168.1.109   HTTP/XML   52102   f4:4d:30:6c:b0:a1   42448   1032   NOTIFY /eventSub HTTP/1.1
which closed the connection. Playback continued.

Maybe the SUBSCRIBE events has more to do with playback being successful in this trace:
41348   336.147951   192.168.1.109   192.168.1.246   HTTP   2870   00:22:de:8c:ce:10   50704   476   SUBSCRIBE /event/RenderingControl HTTP/1.1
41360   336.162922   192.168.1.109   192.168.1.246   HTTP   2870   00:22:de:8c:ce:10   50704   471   SUBSCRIBE /event/AVTransport HTTP/1.1
keeping the connection alive.

At the end of the second track there is another NOTIFY event.
41646   376.057739   192.168.1.246   192.168.1.109   HTTP/XML   52102   f4:4d:30:6c:b0:a1   42449   1000   NOTIFY /eventSub HTTP/1.1
followed by requests for Transport Info, so maybe that is how the Primare tells MC is has finished playing that track.



You are right though Zybex. There are no EVENT frames in Log8, where playback fails on the first track.

So here is a theory:
MC thinks it is using Transport Event mode, so it doesn't use Polling Mode and hence playback fails. So either:
a) The Primare for some reason doesn't always send Transport Events.
b) Or possibly for some reason, with the NUC, those packets are being blocked by the firewall, if they are received by the NUC without previous communication, and hence seen as an intrusion attempt.

Solving a) would require visibility of internal errors in the Primare, probably. Unless MC needs to tell the Primare to use Event mode, and isn't? I can't see anywhere that MC tells the Primare to use Event mode when playback works.
Solving b) could be done by removing all firewalls, but I think that was already done. Visibility to confirm the packets are being sent by the Primare, or not, would require a switch with port monitoring/mirroring so Wireshark could see all packets on the network.


EDIT: Thanks Scobie.

[RalphBrooks]

Not sure how long you were there or exactly what group you were in, but I was the lead workstation analysis at IDC when Intel based systems starting taking over the workstation market from Unix based systems. I worked with many people in the Intel PC group in those days, including Dileep Bandarkar, who was an old friend from Digital days. Fun times.

32 years at Intel working in the client systems group under one name or another.  Started in 1984 on Multibus I/O controllers and then started working on PC's when Intel first got into the PC business with the Intel 301 desktop motherboard. Yes I knew Dileep.

[RalphBrooks]

Look, I also have an Oppo 105, so do you want to send me the troublesome files in your playlist, so I can test them on my player?

Sure thing, I've uploaded two folders to my google drive.
Original 7-walkers album I choose to work with.  Tracks 2 and 12 demonstrated high rate of hangs.
https://drive.google.com/drive/folders/1dcJOm2uSvmWtQnsbadsq8K2jdk5zx6qa?usp=sharing

Test album 7_Walker_test_3 which is track 12 off that album repeated 10 time with most of the meta data removed. 
https://drive.google.com/drive/folders/11Weo_LrFETQVqPGm553wrJGb-yGH1kat?usp=sharing

I'd be interested if you can reproduce/experience the same issue I have.  I can now repeat failures on both NUC as well as my Laptop (once I ensure the polling setting is not enabled) .

[RalphBrooks]

Lovely summary again Zybex.

Some confusion over the "Ignore Transport Events (Use Polling Mode)" setting. I think it was sorted over multiple posts, but...

When it is ticked, MC doesn't use Event style transport control, but uses Polling Mode, and that does indeed work for Ralph. But using Transport Events is better. I think it is required for proper Gapless? Not sure. Bob?
When it is not ticked, MC uses Event style transport control. This is what Ralph has been testing.

It sounds like in logs 7, 9, and 10, Event style control was working. But in log 8 it wasn't. In all cases it was turned on, and should have been working.



I saw Event Subscriptions in traces where playback stalled, but I didn't check for each track. Maybe there is no Event Subscription, or no matching NOTIFY for the failed tracks.

There are still some mysteries:
1. Why does the Primare RESET the transfer? There is no obvious reason in the trace. It could just be a bug in the Primare firmware, but...
2. Why does playback work on the laptop, but not on the NUC, for basically "the same" files, and fairly consistently?

The reason for 1. could be some sort of packet flood control, where the Primare gets overwhelmed and so says "start again". That would point to the NIC or OS settings on the NUC versus the Laptop. Hence Wer's suggestion, I suspect, to test with a USB NIC. But the transfer rate seems to be only about 3.888 Mbps, so that shouldn't be an issue.


Also @Bob, this change looks like it should address the issue of the Renderer not issuing an Event/NOTIFY to report completion of a track when Transport Events is being used. Is that code still there and working?

24.0.36 (6/20/2018)
12. Changed: DLNA, Add a code that will do a manual transport state update if we look frozen at the end of a track (missed an event..)



This has been a good thread, because there have been lots of DLNA threads that never quite get to the bottom of why something wasn't quite working. If there was a cause found, maybe the problems other people experience could be eliminated.

In answer to your second "mystery" questions above, I could initially reproduce the failure using my laptop as the MC server, but then it just stopped failing.  I have confirmed it stopped failing and the odd behavior I reported in my later log reports were a result of the polling mode still being set, even though it showed unchecked.  As noted by Bob,  to ensure changes to the DLNA Options setting I needed to restart JRiver after making any change (clearly I did not do this evert time).  I tried doing it (I even went so far as rebooting the laptop) and retested with my 7 Walkers_test_3 test album and could again reproduce the failures on the first or second track, just like my NUC experiences. Whew, my test results make more sense now...

[wer]

Ralph, if you're now getting consistent results between the NUC and PC, I no longer think it's important to do the test with the USB ethernet adapter.  That was intended to minimize software (driver) differences in behavior on the presumption that the MC configuration had already been aligned.  Since we now know the MC config wasn't really aligned, and once it is you get consistent results, I don't think the driver change will reveal anything new.

Unless I missed something in your reports, you still do consistently have "good" tracks and "bad" tracks (subject to some minor randomness), correct?

If so then I still think we have a data driven problem.

I still think it might be interesting to do the 50x download test with hashing.

I would be even more interested to see how your Bluray player cooperates with a different DLNA server, like Bubble or anything else able to do the job, using the exact same files.

There is still potential for determining whether the device or MC is more at fault, although of course if it falls on the device side there might be no potential for a fix.

[zybex]

Some confusion over the "Ignore Transport Events (Use Polling Mode)" setting. I think it was sorted over multiple posts, but...
When it is not ticked, MC uses Event style transport control. This is what Ralph has been testing.

I think the option logic may be switched, from what Ralph said. Can one of you quickly test it please? (I don't use DLNA)
- Enable the "Ignore Transport Events (Use Polling Mode)"
- restart MC
- capture a 1-file playback
- open the capture, filter by 'http', and check if there's a NOTIFY packet near the top (or filter by 'http.request.method == "NOTIFY" && http')
- repeat with the option disabled

I saw Event Subscriptions in traces where playback stalled, but I didn't check for each track. Maybe there is no Event Subscription, or no matching NOTIFY for the failed tracks.

Every single failed playback I saw lacked the EVENTs.

There are still some mysteries:
1. Why does the Primare RESET the transfer? There is no obvious reason in the trace. It could just be a bug in the Primare firmware, but...

I think it's just the way the Primare is implemented. FLAC files always work on the 5th transfer, so it's not exactly random. Something like this may be going on inside Primare's head (note that the filename/extension is likely ignored by these players, as not all DLNA servers/controllers will provide it, especially on Macs):
- Controller: Hmm, I got a request to play this stream... Hey WAVCODEC, play this
- WAVCODEC: Sure! Downloading... hmmm, this doesn't look like my thing! Aborting!
- Controller: Are you sure? Try again with these parameters
- WAVCODEC: OK! Downloading... hmmm, still can't read it. Aborting!
- Controller: Dang. Hey MP3CODEC, play this!
- MP3CODEC: Sure! Downloading... Dang, who wrote this? It's crap! Aborting!
- Controller: Are you sure? Try again with these parameters
- MP3CODEC: If you insist. Downloading... Nah, must be some of that post-modern crap. Aborting!
- Controller: No need to be rude. Hey FLACCODEC, play this!
- FLACCODEC: Alright, Downloading... Looks good, Playing...

2. Why does playback work on the laptop, but not on the NUC, for basically "the same" files, and fairly consistently?

We figured out this was due to not restarting MC after changing options, so EVENTs were still enabled.

[zybex]

In this Log7 where playback worked, at the end of the first track I can see the frame:
20768   190.557669   192.168.1.246   192.168.1.109   HTTP/XML   52102   f4:4d:30:6c:b0:a1   58123   1000   NOTIFY /eventSub HTTP/1.1

But I can't really relate that to the Renderer telling MC that playback has finished for the track.

The XML content for that packet contains "TransportState val=STOPPED". 20771 is just the 200 OK/Ack for 20768. Since this is an independent TCP connection, it is closed (FIN) after the 200 OK. After this MC double-checks by doing a couple of GetTransportInfo calls.

There are other EVENT Subscription frames that just appear in the middle of nowhere:

25437 is the PLAYING notification, it contains "TransportState val='PLAYING'"

There is a very late response to a GET, and the response is what MC usually sends for a HEAD frame, "Partial Content":
26683   191.928707   192.168.1.246   192.168.1.109   HTTP   52100   f4:4d:30:6c:b0:a1   45220   191   GET /Music/F590337.flac?Reader=10 HTTP/1.1
41179   321.235456   192.168.1.109   192.168.1.246   HTTP   45220   00:22:de:8c:ce:10   52100   413   HTTP/1.1 206 Partial Content  (audio/x-flac)
but playback continues without a RESET.

That's just the last packet of the entire file transfer, which ends there, about 2 minutes into playback. It's a 206 "Partial" because the player skipped the first 128KB on the request.

Another EVENT in the middle of nowhere:
41373   336.166634   192.168.1.246   192.168.1.109   HTTP/XML   52102   f4:4d:30:6c:b0:a1   42448   1032   NOTIFY /eventSub HTTP/1.1
which closed the connection. Playback continued.

Maybe the SUBSCRIBE events has more to do with playback being successful in this trace:
41348   336.147951   192.168.1.109   192.168.1.246   HTTP   2870   00:22:de:8c:ce:10   50704   476   SUBSCRIBE /event/RenderingControl HTTP/1.1
41360   336.162922   192.168.1.109   192.168.1.246   HTTP   2870   00:22:de:8c:ce:10   50704   471   SUBSCRIBE /event/AVTransport HTTP/1.1
keeping the connection alive.

At the end of the second track there is another NOTIFY event.
41646   376.057739   192.168.1.246   192.168.1.109   HTTP/XML   52102   f4:4d:30:6c:b0:a1   42449   1000   NOTIFY /eventSub HTTP/1.1
followed by requests for Transport Info, so maybe that is how the Primare tells MC is has finished playing that track.

Check the XML data to see what the notifications are saying. Some of them are just in response to [re]SUBSCRIBE packets that MC sends, apparently periodically too. Others are a notification of a state change. In all cases, a NOTIFY sequence is an independent TCP conversation/connection, with the corresponding SYN and FIN packets. This is not closing the main playback connection.

So here is a theory:
MC thinks it is using Transport Event mode, so it doesn't use Polling Mode and hence playback fails. So either:
a) The Primare for some reason doesn't always send Transport Events.
b) Or possibly for some reason, with the NUC, those packets are being blocked by the firewall, if they are received by the NUC without previous communication, and hence seen as an intrusion attempt.

The Primare only sends EVENTs if MC sends a SUBSCRIBE to it. Depending on that "ignore transport events" setting, MC will Subscribe or not... As I've said, I think that option may be misbehaving.
It's not the firewall - these are all HTTP connections, and we can see them on the trace capture.

[zybex]

Unless I missed something in your reports, you still do consistently have "good" tracks and "bad" tracks (subject to some minor randomness), correct?
If so then I still think we have a data driven problem.
I still think it might be interesting to do the 50x download test with hashing.

The FLAC files contain an MD5 signature of the data. I extracted it from the PCAP file (which failed playback) and tested it with "flac -t". It passed, meaning that there was no data corruption in the captured packets. If there was a transmission problem after that, the TCP CRC mechanism would just retransmit the bad packet. If there's any additional data corruption it would have to occur after reception by the Primare.

I think it's clear that playback stops because the Player doesn't reach the last second, it stops a bit early (and with EVENTS disabled, MC doesn't detect this condition). This can be easily explained by timestamp rounding/truncation by the Primare. The FLAC contains duration in Frames, not seconds, so some math is needed to get the correct total duration. Looking at one of the files (3:04) It's clear that the Primare does this correctly as it reports length=3:04. But maybe some subsystem of the Primare uses a different/buggy calculation method and finishes the stream at 3:03, or skips some frames so they don't add up to 3:04, or is thrown off by those skipped 128KB, or just doesn't update the total after the last frame is played. So the last position is reported at 3:03, triggering the whole problem.

This would only affect some files. This particular file size is exactly 3:04.04. These 0.04 of a second are covered by a single frame in the FLAC file (last frame), which starts at 3:03.935 - so it's very likely an off-by-1 bug or not updating for the last frame, reporting instead the (truncated) final position of 3:03. This would only be a problem in files with durations very close to the last second - if this file had a single extra frame or was above 3:04.11, it would probably already report 3:04 (each frame on this file covers 0.1045 seconds)

TLDR: Some particular file durations + lack of Events + bug in Primare = playback stops.

I think this is not worth pursuing any further, as we now know that it works fine with EVENTs.

[dtc]

32 years at Intel working in the client systems group under one name or another.  Started in 1984 on Multibus I/O controllers and then started working on PC's when Intel first got into the PC business with the Intel 301 desktop motherboard. Yes I knew Dileep.

Small world. Those were good days. I have been retired for a while now. You will enjoy it

[AndrewFG]

Please try transcoding your files to L16. Just that.

[RoderickGI]

I think the option logic may be switched, from what Ralph said. Can one of you quickly test it please? (I don't use DLNA)

I tested this playing to BubbleUPnP on my Android phone, acting as a DLNA Renderer. Best I can do.

I made sure the DLNA Server I was using in MC was associated with BubbleUPnP on the phone. For these tests I also had SetNext support disabled, just for simplicity.

Case 1 - Using Polling Mode
I ticked the "Ignore Transport Events (Use Polling Mode)" setting then restarted MC, then checked the settings was still ticked.
Then I played Track 1 from the "7 Walkers_test_3" file set. It played right through with no issue.
I filtered the trace down to just the IP Address on the phone and then searched for "eventSub" in the packet list. I found no instances of "eventSub".
I confirmed that using the "http.request.method == "NOTIFY" && HTTP" filter.

Case 2 - Using EVENTS
I then repeated the test, unticking the "Ignore Transport Events (Use Polling Mode)" setting restarting MC, then checked the settings was still unticked.
Again I played Track 1 from the "7 Walkers_test_3" file set. It played right through with no issue.
I filtered the trace down to just the IP Address on the phone and then searched for "eventSub" in the packet list. I found three instances of "eventSub" in frames of the form:
521   3.210276   192.168.0.11   192.168.0.10   HTTP/XML   52105   6c:f0:49:ef:0c:93   44891   875   NOTIFY /eventSub HTTP/1.1
The first noted the AVTransportURI with "AVTransportURI val="http://192.168.0.10:52102/Music/F1211527.flac".
The second confirmed MC was playing with "TransportState val="PLAYING".
The third noted playback had stopped with "TransportState val="STOPPED".
I confirmed that using the "http.request.method == "NOTIFY" && HTTP" filter.

Case 3 - EVENTS wth SetNext (maybe)
Just for completeness I turned on setNext support, and with the "Ignore Transport Events (Use Polling Mode)" setting unticked tested again, and EVENTS were still being used. So no undesirable interaction between those two settings. I believe Ralph has SetNext turned off?   Hmmm, SetNext was Disabled again after playing the file. That was supposed to be fixed. I'll have to look into that again.


My conclusion, at least when using BubbleUPnP, is that the "Ignore Transport Events (Use Polling Mode)" setting is working correctly as per the setting name.

So I agree with this:

Every single failed playback I saw lacked the EVENTs.

On the NUC, as per Reply #104:
Log7, succeeded, has EVENTS.
Log8, failed, has no EVENTS.
Log9, succeeded, has EVENTS.
Lo10, succeeded, has EVENTS.

[RoderickGI]

It was all starting to make a little sense, and then I checked for SUBSCRIBE frames in my latest traces...

... there are no SUBSCRIBE frames in either my EVENT or Polling Mode traces. Well, there is one in my Polling Mode trace, but that is between my Workstation and Router.

So, while the MC uses SUBSCRIBE frames when using EVENTS for the Primare, it doesn't for BubbleUPnP. Well, not when one track is played anyway. No wonder DLNA is so difficult to diagnose issues with. It is a wonder it works at all!

[wer]

No wonder DLNA is so difficult to diagnose issues with. It is a wonder it works at all!

Nice try, but I'm still waiting for my stipulation as previously requested.

[RoderickGI]

Nice try, but I'm still waiting for my stipulation as previously requested.

Sorry? Which one was that? Was I asleep at the time?

[wer]

Very likely.

https://yabb.jriver.com/interact/index.php/topic,120982.msg883396.html#msg883396

[RoderickGI]

Duly publicly acknowledged, both that DLNA is a PITA and that you show greater wisdom than me... although I don't really use DLNA all that much. I just want to in future, when I rearrange my network and hardware.

But nevertheless, duly acknowledged!

[AndrewFG]

So, while the MC uses SUBSCRIBE frames when using EVENTS for the Primare, it doesn't for BubbleUPnP.

When a Control Point discovers a renderer it subscribes to TWO services — namely the AVTransport (AVT) and the Renderer Control (RC). This is done with the HTTP SUBSCRIBE method.

Thereafter any actual state changes are sent with HTTP NOTIFY transactions.

As a general rule a SUBSCRIBE may remain valid, unless specifically cancelled, for up to one hour. A subscription may be renewed with a SUBSCRIBE (RENEW) command.

Therefore you are unlikely to see lots of SUBSCRIBEs in your traces. But you should see lots of NOTIFYs.

AFAIK the setting in MC “Ignore Transport Events” does not stop it sending (AVT) SUBSCRIBE. The setting just tells MC to — well — ignore the event NOTIFYs..

[bob]

When a Control Point discovers a renderer it subscribes to TWO services — namely the AVTransport (AVT) and the Renderer Control (RC). This is done with the HTTP SUBSCRIBE method.

Thereafter any actual state changes are sent with HTTP NOTIFY transactions.

As a general rule a SUBSCRIBE may remain valid, unless specifically cancelled, for up to one hour. A subscription may be renewed with a SUBSCRIBE (RENEW) command.

Therefore you are unlikely to see lots of SUBSCRIBEs in your traces. But you should see lots of NOTIFYs.

AFAIK the setting in MC “Ignore Transport Events” does not stop it sending (AVT) SUBSCRIBE. The setting just tells MC to — well — ignore the event NOTIFYs..

IIRC that changed in MC26 at some point to not sending the subscribes. I'd need to double check to be sure...

[RoderickGI]

Thanks Andrew.

It looks like I started my trace after BubbleUPnP had appeared in MC, and so I missed the two SUBSCRIBE frames. I just checked again and they do appear.

I thought they were associated with playback, but I understand now that they are associated with the appearance of a Renderer. At least when EVENTS are being used, rather than Polling Mode.

All good.