squeezbox upnpbridge on Linux (Ubuntu 20.04) loozes connection to upnp Devices

[erikfroijen]

I have squeezebox running on Ubuntu 20.04. I have 3 upnp Device's, 2 Sonos devices and 1 Bose Soundtoche Device. Using UPNPBridge ther is an issue: After a couple of hours connection is lost an no music is playing. Restarting the plugin solves te issue, but this is not what it supposed to be!

Please help out solving this issue

[philippe44]

What version do you use?

[erikfroijen]

Squeezbox version : Logitech Media Server Version: 8.3.0 - 1667251155 @ Fri 04 Nov 2022 09:14:25 AM CET

UPnP/DNLA bridge version: v1.8.2

Last night I just updated Squeeszbox from 8.2.0 to 8.3.0 and uninstalled UPnP/DNLA bridge and installed the version noted in the Plugin list of version 8.3.0

For now it seems like it is more stable!

From: philippe44 @. Sent: 05 November 2022 17:39 To: philippe44/LMS-uPnP @.> Cc: erikfroijen @.>; Author @.> Subject: Re: [philippe44/LMS-uPnP] squeezbox upnpbridge on Linux (Ubuntu 20.04) loozes connection to upnp Devices (Issue #64)

What version do you use?

— Reply to this email directly, view it on GitHub https://github.com/philippe44/LMS-uPnP/issues/64#issuecomment-1304583084 , or unsubscribe https://github.com/notifications/unsubscribe-auth/AOYF2CRDFP5CHM4DF47PP5TWG2EQVANCNFSM6AAAAAARXR5OZA . You are receiving this because you authored the thread. https://github.com/notifications/beacon/AOYF2CR2GUD6KZHKU546ZUDWG2EQVA5CNFSM6AAAAAARXR5OZCWGG33NNVSW45C7OR4XAZNMJFZXG5LFINXW23LFNZ2KUY3PNVWWK3TUL5UWJTSNYJN2Y.gif Message ID: @. @.> >

[orosoiu]

I have the same issue, running the latest version of LMS and UPnP bridge (v1.82.2), but it happened constantly on older versions as well. Receiver stops playing randomly after a prolongued session (several hours). LMS keeps trying to play songs, and the UI shows the songs changing, but nothing is playing on the receiver and nothing more is added to the logs. Manually pressing Next Track fixes the issue (receiver starts playing again and logging resumes).

This is what the log shows at the time when issue is happening:

[19:53:55.945871] _SyncNotifState:687 Living Room Hi-Fi: uPNP playing
[19:53:56.459573] sendSTAT:169 [0x104bb1540]: STAT:[STMs] msplayed 0
[19:59:11.430708] output_http_thread:306 [0x104bb1540]: draining (60762266 bytes)
[19:59:11.651743] output_http_thread:258 [0x104bb1540]: self-exit 
[19:59:11.651895] output_http_thread:389 [0x104bb1540]: end thread 0 (61286064 bytes)
[19:59:30.006674] sendSTAT:169 [0x104bb1540]: STAT:[STMd] msplayed 333000
[19:59:30.042353] process_strm:238 [0x104bb1540] strm command s
[19:59:30.042390] process_strm:307 [0x104bb1540], strm s autostart: 1 transition period: 10 transition type: 0 codec: p
[19:59:30.042400] sendSTAT:169 [0x104bb1540]: STAT:[STMf] msplayed 333000
[19:59:30.047209] output_start:81 [0x104bb1540]: start thread 0
[19:59:30.047323] sq_callback:343 [0x104c3bf00]:
    artist:[snip]
    album:[snip]
    title:[snip]
    genre:
    duration:195.800
    size:0
    cover:[snip]
    offset:1
[19:59:30.047349] sq_callback:369 [0x104c3bf00]: next URI gapped (s:0) http://192.168.100.100:53022/bridge-359.pcm
[19:59:30.047363] process_start:1220 [0x104bb1540]: codec:p, ch:2, s:16, r:44100
[19:59:30.047566] sendSTAT:169 [0x104bb1540]: STAT:[STMc] msplayed 333000
[19:59:43.915977] AVTSetURI:91 [0x104c3bf00]: uPNP setURI http://192.168.100.100:53022/bridge-359.pcm (cookie 0x48e13)
[19:59:43.916246] AVTPlay:151 [0x104c3bf00]: uPNP play (cookie 0x48e14)
[19:59:43.916287] _SyncNotifState:664 [0x104c3bf00]: gapped transition (null)
[19:59:43.978799] output_http_thread:157 [0x104bb1540]: got HTTP connection 17
[19:59:44.414114] _SyncNotifState:687 Living Room Hi-Fi: uPNP playing
[19:59:44.917297] sendSTAT:169 [0x104bb1540]: STAT:[STMs] msplayed 0
[20:00:14.198651] _SyncNotifState:659 [0x104c3bf00]: uPNP stop

The only difference I can spot vs a normal play is that last line which is only logged when this issue occurs:

[20:00:14.198651] _SyncNotifState:659 [0x104c3bf00]: uPNP stop

Receiver is Yamaha R-N602 if it matters.

[erikfroijen]

I have looked in my old log files and see this error:

[00:47:24.002116] process:500 [0xbc3ad0] strm

[00:47:24.002206] process_strm:241 [0xbc3ad0] strm command t

[00:47:24.002231] sendSTAT:169 [0xbc3ad0]: STAT:[STMt] msplayed 18744000

[00:47:24.002871] process:500 [0xbbb140] strm

[00:47:24.002944] process_strm:241 [0xbbb140] strm command t

[00:47:24.002969] sendSTAT:169 [0xbbb140]: STAT:[STMt] msplayed 0

[00:47:24.077747] sq_notify:691 [0xbc3ad0] time 18745000 18745000

[00:47:24.077810] ActionHandler:898 [0xc49150]: position 18745000 (cookie 0x976d)

[00:47:24.083784] read_line:589 fd: 23 read error: 104 Connection reset by peer

[00:47:24.083890] http_parse:513 cannot read method

[00:47:24.083907] handle_http:478 [0xbbb140]: http parsing error (null)

[00:47:24.083920] output_http_thread:209 [0xbbb140]: HTTP close 23 (bytes 589249) (n:1 res:0)

[00:47:24.083978] output_http_thread:157 [0xbbb140]: got HTTP connection 23

[00:47:24.085004] handle_http:483 [0xbbb140]: received HEAD /bridge-1.mp4 HTTP/1.1

[00:47:24.085139] handle_http:486 [0xbbb140]: HTTP headers

CONNECTION: close^M

Host: 10.2.10.40:37099^M

USER-AGENT: Linux UPnP/1.0 Sonos/70.1-34112 (ZPS22)^M

X-Sonos-SWGen: 2^M

X-Sonos-Firmware: 70.1-34112^M

X-Sonos-Muse-Api: 1.30.0^M

X-Sonos-Id-Hash: pcx1rhTkQBAseZ/BDj7tLeZwX/2m5D1hI1Bne92m1HM=^M

[00:47:24.085201] handle_http:491 [0xbbb140]: Sonos mode

HTTP/1.1 200 OK^M

Server: squeezebox-bridge^M

Connection: close^M

Content-Type: audio/mp4^M

^M

From: Ovidiu Rosoiu @. Sent: 05 November 2022 19:10 To: philippe44/LMS-uPnP @.> Cc: erikfroijen @.>; Author @.> Subject: Re: [philippe44/LMS-uPnP] squeezbox upnpbridge on Linux (Ubuntu 20.04) loozes connection to upnp Devices (Issue #64)

I have the same issue, running the latest version of LMS and UPnP bridge. Receiver stops playing randomly after a prolongued session (several hours). This is what the log shows:

[19:53:55.945871] _SyncNotifState:687 Living Room Hi-Fi: uPNP playing [19:53:56.459573] sendSTAT:169 [0x104bb1540]: STAT:[STMs] msplayed 0

[19:59:11.651895] output_http_thread:389 [0x104bb1540]: end thread 0 (61286064 bytes) [19:59:30.006674] sendSTAT:169 [0x104bb1540]: STAT:[STMd] msplayed 333000 [19:59:30.042353] process_strm:238 [0x104bb1540] strm command s [19:59:30.042390] process_strm:307 [0x104bb1540], strm s autostart: 1 transition period: 10 transition type: 0 codec: p [19:59:30.042400] sendSTAT:169 [0x104bb1540]: STAT:[STMf] msplayed 333000 [19:59:30.047209] output_start:81 [0x104bb1540]: start thread 0 [19:59:30.047323] sq_callback:343 [0x104c3bf00]: artist:[snip] album:[snip] title:[snip] genre: duration:195.800 size:0 cover:[snip] offset:1 [19:59:30.047349] sq_callback:369 [0x104c3bf00]: next URI gapped (s:0) http://192.168.100.100:53022/bridge-359.pcm [19:59:30.047363] process_start:1220 [0x104bb1540]: codec:p, ch:2, s:16, r:44100 [19:59:30.047566] sendSTAT:169 [0x104bb1540]: STAT:[STMc] msplayed 333000 [19:59:43.915977] AVTSetURI:91 [0x104c3bf00]: uPNP setURI http://192.168.100.100:53022/bridge-359.pcm (cookie 0x48e13) [19:59:43.916246] AVTPlay:151 [0x104c3bf00]: uPNP play (cookie 0x48e14) [19:59:43.916287] _SyncNotifState:664 [0x104c3bf00]: gapped transition (null) [19:59:43.978799] output_http_thread:157 [0x104bb1540]: got HTTP connection 17 [19:59:44.414114] _SyncNotifState:687 Living Room Hi-Fi: uPNP playing [19:59:44.917297] sendSTAT:169 [0x104bb1540]: STAT:[STMs] msplayed 0 [20:00:14.198651] _SyncNotifState:659 [0x104c3bf00]: uPNP stop

— Reply to this email directly, view it on GitHub https://github.com/philippe44/LMS-uPnP/issues/64#issuecomment-1304603435 , or unsubscribe https://github.com/notifications/unsubscribe-auth/AOYF2CV4SRFBWWLPEWB4YSTWG2PIHANCNFSM6AAAAAARXR5OZA . You are receiving this because you authored the thread. https://github.com/notifications/beacon/AOYF2CSHHO36BNWAA3WBZEDWG2PIHA5CNFSM6AAAAAARXR5OZCWGG33NNVSW45C7OR4XAZNMJFZXG5LFINXW23LFNZ2KUY3PNVWWK3TUL5UWJTSNYKVSW.gif Message ID: @. @.> >

[philippe44]

Please update to the dev version (see here https://forums.slimdevices.com/showthread.php?103728-Announce-UPnPBridge-integrate-UPnP-DLNA-players-with-LMS-(squeeze2upnp))

[orosoiu]

Thank you for the quick response! I have updated LMS to latest version and the plugin to latest dev version (v2.0.4). Will let you know if I see any issues.

[erikfroijen]

I Have installed te 2.0.4 dev version.

Now wait and see!

From: philippe44 @. Sent: 05 November 2022 19:39 To: philippe44/LMS-uPnP @.> Cc: erikfroijen @.>; Author @.> Subject: Re: [philippe44/LMS-uPnP] squeezbox upnpbridge on Linux (Ubuntu 20.04) loozes connection to upnp Devices (Issue #64)

Please update to the dev version (see here https://forums.slimdevices.com/showthread.php?103728-Announce-UPnPBridge-integrate-UPnP-DLNA-players-with-LMS-(squeeze2upnp))

— Reply to this email directly, view it on GitHub https://github.com/philippe44/LMS-uPnP/issues/64#issuecomment-1304608363 , or unsubscribe https://github.com/notifications/unsubscribe-auth/AOYF2CX7DAEQMWJU6E7PK4LWG2STRANCNFSM6AAAAAARXR5OZA . You are receiving this because you authored the thread. https://github.com/notifications/beacon/AOYF2CTDOLEYV5SLC3CQYWTWG2STRA5CNFSM6AAAAAARXR5OZCWGG33NNVSW45C7OR4XAZNMJFZXG5LFINXW23LFNZ2KUY3PNVWWK3TUL5UWJTSNYK7GW.gif Message ID: @. @.> >

[orosoiu]

Unfortunately the issue is still there even with the latest dev version. Same behaviour: receiver stops playing after a prolongued session even though the LMS UI shows as still playing and keeps progressing from song to song, but no streams are sent to the receiver any longer.

Same ouput in the logs, nothing peculiar; one thing I noticed is that the "uPNP stop" line is logged even for tracks that played fine so I think that is a red herring, in which case there is zero information in the logs to indicate what the problem might be.

[19:21:20.046864] output_start:82 [0x10ad6d0a0]: start thread 0
[19:21:20.046944] sq_callback:334 [0x10adf7a80]:
    artist:Ark
    album:Burn the Sun
    title:Just a Little
    genre:
    duration:276.520
    size:0
    cover:http://192.168.100.100:9000/imageproxy/https%3A%2F%2Fi.scdn.co%2Fimage%2Fab67616d0000b273ba71cf875d63a6aac2697dea/image.png
    offset:1
[19:21:20.046962] sq_callback:365 [0x10adf7a80]: next URI gapped (s:0) http://192.168.100.100:52299/bridge-142.pcm
[19:21:20.046970] process_start:1221 [0x10ad6d0a0]: codec:p, ch:2, s:16, r:44100
[19:21:20.047122] sendSTAT:169 [0x10ad6d0a0]: STAT:[STMc] msplayed 223000
[19:21:34.618720] MRThread:575 [0x10adf7a80] overtime next track
[19:21:34.619081] AVTSetURI:78 [0x10adf7a80]: uPNP setURI http://192.168.100.100:52299/bridge-142.pcm (cookie 0x27364)
[19:21:34.619332] AVTPlay:138 [0x10adf7a80]: uPNP play (cookie 0x27365)
[19:21:34.663091] output_http_thread:158 [0x10ad6d0a0]: got HTTP connection 18
[19:21:35.131949] _SyncNotifState:686 Living Room Hi-Fi: uPNP playing
[19:21:35.132221] sendSTAT:169 [0x10ad6d0a0]: STAT:[STMs] msplayed 0
[19:22:04.913512] _SyncNotifState:660 [0x10adf7a80]: uPNP stop
[19:23:56.789361] output_http_thread:390 [0x10ad6d0a0]: end thread 0 (0 bytes)
[19:23:56.789870] AVTStop:204 [0x10adf7a80]: uPNP stop (cookie 0x2750c)
[19:23:56.810058] process_strm:238 [0x10ad6d0a0] strm command s
[19:23:56.810113] process_strm:306 [0x10ad6d0a0], strm s autostart: 1 transition period: 10 transition type: 0 codec: p
[19:23:56.810126] sendSTAT:169 [0x10ad6d0a0]: STAT:[STMf] msplayed 0
[19:23:56.815601] output_start:82 [0x10ad6d0a0]: start thread 0
[19:23:56.815688] sq_callback:334 [0x10adf7a80]:
    artist:Native Construct
    album:Quiet World
    title:Come Hell or High Water
    genre:
    duration:354.906
    size:0
    cover:http://192.168.100.100:9000/imageproxy/https%3A%2F%2Fi.scdn.co%2Fimage%2Fab67616d0000b27328e32ee7aa94ac26ba6cf004/image.png
    offset:0
[19:23:56.815705] sq_callback:378 [0x10adf7a80]: set current URI (s:0) http://192.168.100.100:52835/bridge-143.pcm
[19:23:56.815765] AVTSetURI:78 [0x10adf7a80]: uPNP setURI http://192.168.100.100:52835/bridge-143.pcm (cookie 0x2750d)
[19:23:56.815893] process_start:1221 [0x10ad6d0a0]: codec:p, ch:2, s:16, r:44100
[19:23:56.816095] sendSTAT:169 [0x10ad6d0a0]: STAT:[STMc] msplayed 0
[19:23:57.106312] _SyncNotifState:660 [0x10adf7a80]: uPNP stop

Server info:

    Version: 8.3.0 - 1667251155 @ Fri Nov 4 09:12:16 CET 2022
    Hostname: -
    Server IP Address: 192.168.100.100
    Operating system: macOS 11.6.8 - EN - utf8
    Platform Architecture: x86_64
    Perl Version: 5.34.0 - darwin-thread-multi-2level
    Audio::Scan: 1.05
    IO::Socket::SSL: 2.072
    Database Version: DBD::SQLite 1.58 (sqlite 3.22.0)
...
    UPnP/DLNA bridge 2.0.5

[philippe44]

I have squeezebox running on Ubuntu 20.04. I have 3 upnp Device's, 2 Sonos devices and 1 Bose Soundtoche Device. Using UPNPBridge ther is an issue: After a couple of hours connection is lost an no music is playing. Restarting the plugin solves te issue, but this is not what it supposed to be!

When you hit "next" on the LMS UI, does playback restart or is the only solution to restart the plugin?

[orosoiu]

For me, the playback resumes when I hit "next", I don't need to restart the plugin.

[erikfroijen]

L.S.

The onle way is to restart the plugin!

I have updated to 2.0.4 dev version but with the same result, Just as Ovidiu Rosoiu described!

From: philippe44 @. Sent: 07 November 2022 18:55 To: philippe44/LMS-uPnP @.> Cc: erikfroijen @.>; Author @.> Subject: Re: [philippe44/LMS-uPnP] squeezbox upnpbridge on Linux (Ubuntu 20.04) loozes connection to upnp Devices (Issue #64)

I have squeezebox running on Ubuntu 20.04. I have 3 upnp Device's, 2 Sonos devices and 1 Bose Soundtoche Device. Using UPNPBridge ther is an issue: After a couple of hours connection is lost an no music is playing. Restarting the plugin solves te issue, but this is not what it supposed to be!

When you hit "next" on the LMS UI, does playback restart or is the only solution to restart the plugin?

— Reply to this email directly, view it on GitHub https://github.com/philippe44/LMS-uPnP/issues/64#issuecomment-1305978476 , or unsubscribe https://github.com/notifications/unsubscribe-auth/AOYF2CTWKHBMMYGU3OLP6DTWHE65RANCNFSM6AAAAAARXR5OZA . You are receiving this because you authored the thread. https://github.com/notifications/beacon/AOYF2CSCLLR2DHPGR2RE3ZTWHE65RA5CNFSM6AAAAAARXR5OZCWGG33NNVSW45C7OR4XAZNMJFZXG5LFINXW23LFNZ2KUY3PNVWWK3TUL5UWJTSN26TGY.gif Message ID: @. @.> >

[philippe44]

Understood except that @orosoiu can resume playback by hitting "next". Can you attach a log of what's happening when you do that?

[erikfroijen]

I enclosed a zipped log when tis happens!

From: philippe44 @. Sent: 07 November 2022 20:28 To: philippe44/LMS-uPnP @.> Cc: erikfroijen @.>; Author @.> Subject: Re: [philippe44/LMS-uPnP] squeezbox upnpbridge on Linux (Ubuntu 20.04) loozes connection to upnp Devices (Issue #64)

Understood except that @orosoiu https://github.com/orosoiu can resume playback by hitting "next". Can you attach a log of what's happening when you do that?

— Reply to this email directly, view it on GitHub https://github.com/philippe44/LMS-uPnP/issues/64#issuecomment-1306085651 , or unsubscribe https://github.com/notifications/unsubscribe-auth/AOYF2CWHZ4N7V53AVY3HGGTWHFJ3LANCNFSM6AAAAAARXR5OZA . You are receiving this because you authored the thread. https://github.com/notifications/beacon/AOYF2CVE4AR6ICDA3W4L3ATWHFJ3LA5CNFSM6AAAAAARXR5OZCWGG33NNVSW45C7OR4XAZNMJFZXG5LFINXW23LFNZ2KUY3PNVWWK3TUL5UWJTSN3FERG.gif Message ID: @. @.> >

[philippe44]

Sorry but there is nothing attached. Can you use the web interface of github instead? I think you are using some kind of email proxy that makes the layout of your response very difficult.

[erikfroijen]

Here the lo files in zip trough the website. upnpbridge.zip

Regards, Erik

[orosoiu]

A small update: I just updated the plugin to the latest version (2.0.7.2) and now the playback sometimes stops in the middle of the track. As before, clicking "Next Track" resumes playback. Don't know if it's the same issue or related; log excerpt below:

[17:20:59.030305] _SyncNotifState:688 Living Room Hi-Fi: uPNP playing
[17:20:59.030625] sendSTAT:169 [0x1018930e0]: STAT:[STMs] msplayed 0
[17:24:31.063026] MRThread:580 [0x10191dac0] overtime last track
[17:24:31.063113] AVTBasic:188 [0x10191dac0]: uPNP Stop (cookie 0x18a6)
[17:24:31.088004] http_read_line:755 fd: 28 read error: Connection reset by peer
[17:24:31.088084] http_parse_simple:678 cannot read method
[17:24:31.088103] handle_http:479 [0x1018930e0]: http parsing error (null)
[17:24:31.088118] output_http_thread:210 [0x1018930e0]: HTTP close 28 (bytes 34161106) (n:2 res:0)
[17:24:31.578875] _SyncNotifState:662 [0x10191dac0]: uPNP stop

[philippe44]

You said "now", but it never worked, did it? Ca you add slimproto debug level and send the log? It seems to be related to elapsed time as reported by the player.

[orosoiu]

I meant this is the first time playback stopped in the middle of the track and there were some actual error entries in the log, previously the playback only stopped during a song transition and no errros logged.

I enabled slimproto debug level, will add log here when issue happens again.

[orosoiu]

It happened again, I've attached the log with slimproto debug level enabled. upnpbridge.log.zip