philippe44 / LMS-uPnP

Integrate UPnP players with LogitechMediaServer
108 stars 17 forks source link

GapLess looses connection #67

Closed pmuhlhause closed 1 year ago

pmuhlhause commented 1 year ago

Since the last upgrade, when starting playing an album in GapLess mode set to ‘Force’ , after the second song, the third song is not playing anymore, still showing it playing on LMS but no sound anymore… And if the GapLess mode is set to ‘Yes’ (which I had perfectly running before), then it doesn’t even jump to the second song… Tried all settings combination possible, but no success…. Used with the last version of LMS 8.3 on Ubuntu 22.04 x86 platform. The player is HQPLAYERembedded latest version.

philippe44 commented 1 year ago

HQplayer is a problematic device that should have its UPnP stack fixed. I've decided to remove the dirty workarounds for such devices. You can always send me a log and if there is an issue with the updated implementation of data pipeline, I will fix it, but I will stop making spaghetti code for non-compliant devices

pmuhlhause commented 1 year ago

Ok Philippe, i understand your dilemma, however now I’m stuck with my system (as surely hundreds of other persons if not more) while you have sorted out with Jussi how to solve it in a correct manner. In between, could you please send the procedure on how to rollback to the previous version of your plugin in LMS so to be able to listen to music in between, that would be nice of you?

philippe44 commented 1 year ago

You can go there https://sourceforge.net/projects/lms-plugins-philippe44/files/UPnPBridge-1.82.2.zip/download, this is the last but one version and then you unpack the zip where the plugin is, /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/UPnPBridge (on Linux). I've made many changes including a necessary one to properly respond to servers that behave within the limits of the spec, and the option you were using (I did not know it was used like that) was an inelegant circumvent I did for another problem, so I've decided to solve the issue at the core.

PS: I don't know who/what is Jussi but I still encourage you to send me the log so I can view is there is anything I can do in the boundary of a reasonable HTTP/UPnP streamer, if you want to have the option to use upgrades in the future. New releases are always a pain but usually sort things out and all solo developer that do all this for free ask in return is help (testing) and patience.

pmuhlhause commented 1 year ago

I could downgrade it to the previous version and all is running fine now as before, thank you. I wanted as well to give you some logs, however the plugin updated to 2.1.2 and the process is being unstable, preventing me to catch pertinent logs. You can install a HQP trial version to reproduce the phenomenon, which will be surely easier to get the full insight of what is going wrong (available on all common OS and also as embedded version on RASP4)

pmuhlhause commented 1 year ago

For your information, Jussi Laako is the developer of HQP (Signalyst) Jussi Laako jussi.laako@signalyst.com

philippe44 commented 1 year ago

Catching a log is just clicking on the log button of the plugin interface, that's all

pmuhlhause commented 1 year ago

upnpbridge.log.zip

please find hereby the log I could capture It did work for 3 songs and stopped at the 4th one…. Hoping it helps

pmuhlhause commented 1 year ago

upnpbridge.log.zip

another one starting at 18:24 and stopping at the second song…

philippe44 commented 1 year ago

It's unfortunately the same story. This HTTP/UPnP stacks insists on getting the length of the file that is about to be transferred using HTTP. This is a header named "Content-Length". The RFC2616 makes abundantly clear that this is an optional field as the sender might not know in advance the size of the body it will transmit.

There is also a method which is defined in HTTP 1.1 and must be supported that is named "Chunked-Encoding" to better handling unknown sizes. I think you have tried both options.

When the HTTP server does NOT know the size, there is no content-length field and it is a perfectly valid answer. The server sends the body it has at the time of the request, every time the request for the same resource is made. Now, the UPnP/DLNA field indicates that the head of the body moves so a subsequent request for the same file might change overtime, and that's exactly what happens. The bridges already does its best to memorize a part of the already sent file for potential re-sending, but after a Nth request of the same resource, that beginning is lost.

That HTTP/UPnP stack must be fixed to understand that HTTP transfer with no content-length or in chunked mode if it pretends to be 1.1 is valid and must be supported. You might NEVER know the size of what you'll receive in advance.

pmuhlhause commented 1 year ago

Hello Philippe,

thanks for your analysis, however HQPlayer uses Rygel/GUPnP as UPnP stack. This is open source software, that has also gone through the official DLNA certification process, so how to proceed now? Could you please reintroduce your ‘dirty workaround’ while you can liaise with Rygel so they correct their code accordingly? That will at least ensure service continuity while the codes can be fixed and aligned, what’s your view?

philippe44 commented 1 year ago

Have a look at 2.1.4.

Re DLNA certification, this is an absolute joke and one of the worse certs ever (and I'm working in cellular telecommunication, so I'm used to serious certs). Now, the issue is what HQ player does of what it gets. As said above, the application can insist and force lower layers to (e.g.) get the expected size of the content. This is bad app behavior but you can't blame lower layers that just do what they are told to. There has been tons of "literature" overs the years about that HTTP problem of "I don't know the body size in advance" and at least the answer is always clear: this is 100% acceptable and clients MUST deal with that. The ones that don't are ill-coded.

pmuhlhause commented 1 year ago

Good morning Update applied

this is a test with no-length, GapLess=yes, resume, pause it Is stopping after the first song.

will try another with GapLess=no upnpbridge.log.zip

pmuhlhause commented 1 year ago

This time it passed two songs and stopped at the third one with GapLess=no

upnpbridge.log.zip

pmuhlhause commented 1 year ago

This one with the http mode set to ‘if known’… same issue upnpbridge.log 2.zip

pmuhlhause commented 1 year ago

Last one with no-length, GapLess=yes, seek, stop

stops after the first song upnpbridge.log.zip

Hoping it helps troubleshooting, thank you Philippe

pmuhlhause commented 1 year ago

Hoping it can help, please find some précisions from Jussi on HQP and UPnP:

HQPlayer doesn’t require Content-Length header. For most internet radio streams it is naturally not possible. HPlayer also understands TransferMode.DLNA.ORG header and special unknown content length values through this.

philippe44 commented 1 year ago

The I don't know what to add except that HQP has always been a problem and has never worked correctly with chunked or no content-length, across all UPnP players I've been dealing with

pmuhlhause commented 1 year ago

I understand, however what would you advise, as HQP is a damn good upsampler which I would really like to keep in my system, especially I was using it flawlessly up to version 1.8, so it is definitely possible I suppose. And trust me that I’m not the only one in this situation as many many audiophiles were using your plugin to stream to HQP…now, most of the one I know are seeking for an alternative to LMS to ensure continuity

philippe44 commented 1 year ago

I can only repeat that this apps asks again and again for the same resource for no reasons; below, it's 2 times a "HEAD" and then 2 times a "GET" although the protocolInfo field DIDL has the DLNA_ORG_FLAG_S0_INCREASE flag set which means that the resource has a moving head, so if you keep asking the same thing, you will NOT get the same result. HQPlayer is the sole application that I can remember doing that. It worked in the past because you got lucky the ringbuffer used by this bridge was not rolling over between calls (because of speed)

[11:38:47.501000] handle_http:484 [0xab9f00]: received HEAD /bridge-3.flac HTTP/1.1
[11:38:47.501047] handle_http:487 [0xab9f00]: HTTP headers
Host: 192.168.0.100:58641
getContentFeatures.dlna.org: 1
Connection: close
Accept-Encoding: gzip, deflate
User-Agent: SignalystHQPlayer/4

[11:38:47.501121] handle_http:574 [0xab9f00]: responding:
HTTP/1.1 200 OK
Server: squeezebox-bridge
Connection: close
Content-Type: audio/flac
contentFeatures.dlna.org: DLNA.ORG_OP=00;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=09700000000000000000000000000000

[11:38:47.501143] output_http_thread:210 [0xab9f00]: HTTP close 16 (bytes 0) (n:1 res:0)
[11:38:47.560897] output_http_thread:158 [0xab9f00]: got HTTP connection 16
[11:38:47.561655] handle_http:484 [0xab9f00]: received HEAD /bridge-3.flac HTTP/1.1
[11:38:47.561709] handle_http:487 [0xab9f00]: HTTP headers
Host: 192.168.0.100
Connection: close
User-Agent: SignalystHQPlayer/4
Accept: */*

[11:38:47.561775] handle_http:574 [0xab9f00]: responding:
HTTP/1.1 200 OK
Server: squeezebox-bridge
Connection: close
Content-Type: audio/flac

[11:38:47.561798] output_http_thread:210 [0xab9f00]: HTTP close 16 (bytes 0) (n:1 res:0)
[11:38:47.562144] output_http_thread:158 [0xab9f00]: got HTTP connection 16
[11:38:47.562845] handle_http:484 [0xab9f00]: received GET /bridge-3.flac HTTP/1.1
[11:38:47.562889] handle_http:487 [0xab9f00]: HTTP headers
Host: 192.168.0.100
Connection: close
User-Agent: SignalystHQPlayer/4
Accept: */*

[11:38:47.562960] handle_http:574 [0xab9f00]: responding:
HTTP/1.1 200 OK
Server: squeezebox-bridge
Connection: close
Content-Type: audio/flac

[11:38:47.834145] handle_http:479 [0xab9f00]: http parsing error (null)
[11:38:47.834350] output_http_thread:210 [0xab9f00]: HTTP close 16 (bytes 3637197) (n:1 res:0)
[11:38:47.892767] output_http_thread:158 [0xab9f00]: got HTTP connection 16
[11:38:47.893492] handle_http:484 [0xab9f00]: received HEAD /bridge-3.flac HTTP/1.1
[11:38:47.893531] handle_http:487 [0xab9f00]: HTTP headers
Host: 192.168.0.100
Connection: close
User-Agent: SignalystHQPlayer/4
Accept: */*

[11:38:47.893600] handle_http:574 [0xab9f00]: responding:
HTTP/1.1 200 OK
Server: squeezebox-bridge
Connection: close
Content-Type: audio/flac

[11:38:47.893622] output_http_thread:210 [0xab9f00]: HTTP close 16 (bytes 3637197) (n:1 res:0)
[11:38:47.893881] output_http_thread:158 [0xab9f00]: got HTTP connection 16
[11:38:47.894565] handle_http:484 [0xab9f00]: received GET /bridge-3.flac HTTP/1.1
[11:38:47.894594] handle_http:487 [0xab9f00]: HTTP headers
Host: 192.168.0.100
Connection: close
User-Agent: SignalystHQPlayer/4
Accept: */*

[11:38:47.894619] handle_http:555 [0xab9f00]: re-opening a connection at 3637197
[11:38:47.894636] handle_http:557 [0xab9f00]: head is lost 3637197
[11:38:47.894682] handle_http:574 [0xab9f00]: responding:
HTTP/1.1 200 OK
Server: squeezebox-bridge
Connection: close
Content-Type: audio/flac
philippe44 commented 1 year ago

I've added a "gapless" parameter named "underrun" that will probably solve your issue and that is not too much a dirty trick IMHO. Now, without much hope, I recommend that the HQPlayer developer looks why his stack behaves like that, as it is likely at least not well-configured. As the commercial app vendor, I think it's fair that duty is on his side and your community should push him.

Now, candidly, I admit that my motivation is low for fixing my free app for the benefit of some commercial app whose merit is questionable in my view. I'm saying that, and I realize it's not very nice of me, but I have a master degree in digital signal processing and information's theory (I'm not bragging, it's just to set context) so I don't have a lot of love for what some apps do. Now, I'm not saying at all that the whole application is useless. Things like room correction is nice as well as equalizing to your taste. But the crazy oversampling and search for ultimate bitdepth makes me sigh when you know the theory behind.

Having said that, it's "a large nation" and everybody is entitled to own opinion, as long as they are not dangerous (and crazy like the earth is flat or we did not go on the moon 😄) and I should just leave it and move on...

pmuhlhause commented 1 year ago

Good morning Philippe Thank you for the update…. Being until Wednesday on business trip, I’ll be able to test it on Thursday and will keep you aware accordingly.

pmuhlhause commented 1 year ago

Hello Philippe

‘back home and wanted to test, but your 2.1.7 or even the latest 2.1.12 are not popping up as updates in LMS… should I install them manually?

philippe44 commented 1 year ago

You have to add the dev repository (see 1st post in forum) as I've rolled back to pre 2.x the main repo. Now I would really appreciate if you'd test 2.12.x

pmuhlhause commented 1 year ago

Just performed the test with GapLess=Underrun and also Yes , but same result, being first song starting (with an usual delay of 10s) and then stopping after around 15 s and restarting for 15s and stopping all and over again… please find the log here attached upnpbridge.log.zip

philippe44 commented 1 year ago

Strange - This log seems normal but there is a pause request from LMS. I need to figure out a way to try HQPlayer. I've downloaded the Windows version but it never shows as a UPnP renderer and I can't say that the web site clearly says "here is what you should do for UPnP" - or I missed it

pmuhlhause commented 1 year ago

In fact it doesn’t work from the Desktop version, you’ll need to install on image on a USBKey using ImageWriter for expl. and boot from this key to see HQPLAYER as a UPnP player

https://www.signalyst.com/embedded-install.html?

philippe44 commented 1 year ago

Well, I've tried to verify 2.1.12.2 with HQPlayer but it's a real pain as I can only use a VirtualMachine. Took me some time to realize that this image wants UEFI bios and then it does not really work with the sound board provided by VirtualBox, so I gave up. Let me know if this work for you.

pmuhlhause commented 1 year ago

Oh sorry for this inconvenience… Yes, I’ll test the new version today

pmuhlhause commented 1 year ago

Hello Philippe

just tested the latest .2 dev version, unfortunately the UPnP players discovery doesn’t function anymore, as I cannot see the HQPLAYER neither my Audio Pro speaker which normally pops up dynamically in the players list…

philippe44 commented 1 year ago

There has been no change on that code between .1 and .2. I changed something in .1 so that you can set the name of the interface to force the selection of network. What is your config on that ?

pmuhlhause commented 1 year ago

To confirm, I re-installed the 1.8.x version and all is fine again, players being again visible

For the tests, a simple RPI4 would suffice if you have one, and Jussi told me he would lend you a licence so you don’t need to reboot every 1/2h as per trial version… In the worst case, I would send you a RPI4 configured so you could test?

philippe44 commented 1 year ago

I'm away now but I have a 3B handy. Having said that, I re-tested the detection on 2.1.12.2 on my aarch64 system, after re-installing the plugin and it worked. Would be useful to have your config and/or command line. At least what you ahve set in "Network binding and port"

pmuhlhause commented 1 year ago

Just re-installed the last dev version and erased the config file to be sure. While generating the new config file, I’m getting this error message in the logs:

!!!!!!!!!!!!!!!!!! ERROR LOADING CONFIG FILE !!!!!!!!!!!!!!!!!!!!!

[18:54:35.906881] Start:1449 Cannot load SSL libraries [18:54:35.906903] main:1767 Cannot start, exiting

Retarting Squeeze2upnp after crash: /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/UPnPBridge/Bin/squeeze2upnp-linux-x86_64 -Z -I -b 192.168.0.100 -f /var/log/squeezeboxserver/upnpbridge.log -x /var/lib/squeezeboxserver/prefs/upnpbridge.xml -i /var/lib/squeezeboxserver/prefs/upnpbridge.xml [18:54:44.889558] main:1730 Starting squeeze2upnp version: v2.1.12.2 (Dec 18 2022 @ 08:47:53) [18:54:44.889706] main:1737

!!!!!!!!!!!!!!!!!! ERROR LOADING CONFIG FILE !!!!!!!!!!!!!!!!!!!!!

[18:54:44.890803] Start:1449 Cannot load SSL libraries [18:55:05.890915] Stop:1512 stopping squeezelite devices ... [18:55:05.891133] Stop:1516 terminate update thread ... [18:55:05.891172] Stop:1521 terminate main thread ... [18:55:05.891210] Stop:1524 stopping UPnP devices ...

Retarting Squeeze2upnp after crash: /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/UPnPBridge/Bin/squeeze2upnp-linux-x86_64 -Z -I -b 192.168.0.100 -f /var/log/squeezeboxserver/upnpbridge.log -x /var/lib/squeezeboxserver/prefs/upnpbridge.xml [18:55:05.913660] main:1730 Starting squeeze2upnp version: v2.1.12.2 (Dec 18 2022 @ 08:47:53) [18:55:05.913800] main:1737

philippe44 commented 1 year ago

The SSL libraries fail to load. There was no changes there. Are you 100000% that you did not use the -static version previously?

pmuhlhause commented 1 year ago

Ah ah…. I’m 100% sure that I used the static version, thinking it has all needed libraries

philippe44 commented 1 year ago

Yes but on that log, it is not the static hence the ssl issue

pmuhlhause commented 1 year ago

Apparently after the upgrade it sets it to the no-static version. Now corrected and the discovery is working again.

I made a first test with the GapLess parameter set to underrun, but it failed after the first song (will send you the logs tomorrow).

Then I did a second test with the GapLess parameter set to Yes and this time it worked flawlessly for several songs, with no error messages in the logs…… THAT IS GREAT !!!

I’ll do some extended tests tomorrow, but I think this version should get it right. Thank you Philippe for your great support and pugnacity as you could make it… I’ll give you a final report with a more exhaustive test campaign in the very next days.

philippe44 commented 1 year ago

Great - it’s is very strange, according to our previous discussions, that the underrun does not work where gapless does, but let’s see the log. Thanks for taking them, I know all that is painful

pmuhlhause commented 1 year ago

Please find hereby the logs with GapLess = Yes which I tested extensively and is running perfectly well

upnpbridge.log.zip

pmuhlhause commented 1 year ago

And please find hereby the one with GapLess = underrun which presents an error message for your information

upnpbridge.log 2.zip

philippe44 commented 1 year ago

I'm glad it is working now but looking at these logs I can't see a rational reason why it is now and it was not previously. I'm afraid the issue will come back at some point at the occasion of a release were I'll change something else. I still don't understand why the stack of HQPlayer is making all these bogus HEAD and GET requests, but I guess it is what it is now.

pmuhlhause commented 1 year ago

Just saw you published a .6 version which I’ll test tomorrow… merry Christmas 🎄 to you

pmuhlhause commented 1 year ago

Hello Philippe The latest .6 subversion works flawlessly… by this I will close the issue and thank you a lot.