Sonos system alerts truncated
-
Well pretty sure I didn't change or touch anything! I've turned everything on and off again as one might hope. Excepting a total reboot of the Pi3 that's running all my stuff very reliably in openLuup.
It's all been working well for years and now all of sudden 6 second alerts are truncated to about 4 seconds. Occasionally it works as it should. I see this in the log - does it help?
2023-02-20 09:39:06.662 luup_log:0: My Lua ver 0.50 debug: executing scene 63: "Check windows doors" in room: "Watchers" 2023-02-20 09:39:06.663 luup.call_action:: 217.urn:micasaverde-com:serviceId:Sonos1.Alert 2023-02-20 09:39:06.663 luup.call_action:: action will be handled by parent: 214 2023-02-20 09:39:06.663 luup_log:0: My Lua ver 0.50 debug: rest of scene 63 was executed 2023-02-20 09:39:06.663 luup.scenes:: scene 63, Check windows doors, initiated by AltUI 2023-02-20 09:39:06.665 luup_log:214: Sonos: Alert action on device 217 URI "http://redacted:3480/www/sounds/AllClosed.mp3" duration "6" 2023-02-20 09:39:06.758 luup_log:214: Sonos: UPnP_request (Pause, urn:schemas-upnp-org:service:AVTransport:1): status=1 statusMsg=500 result=[<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><s:Fault><faultcode>s:Client</faultcode><faultstring>UPnPError</faultstring><detail><UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>701</errorCode></UPnPError></detail></s:Fault></s:Body></s:Envelope>] 2023-02-20 09:39:06.759 luup_log:214: stack traceback: ./L_SonosSystem1.lua:265: in function 'error' ./L_SonosUPnP.lua:289: in function <./L_SonosUPnP.lua:169> (tail call): ? ./L_SonosSystem1.lua:3390: in function 'sayOrAlert' ./L_SonosSystem1.lua:3452: in function 'queueAlert' ./L_SonosSystem1.lua:3843: in function <./L_SonosSystem1.lua:3839> (tail call): ? [C]: in function 'pcall' ./openLuup/scheduler.lua:204: in function 'context_switch' ./openLuup/scheduler.lua:366: in function 'dispatch' ./openLuup/scheduler.lua:588: in function 'task_callbacks' ./openLuup/scheduler.lua:699: in function 'start' openLuup/init.lua:354: in main chunk [C]: ? 2023-02-20 09:39:06.888 luup.variable_set:: 214.urn:toggledbits-com:serviceId:SonosSystem1.zoneInfo was: {"zones":{"RINCON_000E58DC7BBE01400":{"Location":"http://redacted3:1400/xml/device_description.xml","Group":"RIN... now: {"zones":{"RINCON_000E58DC7BBE01400":{"Location":"http://redacted3:1400/xml/device_description.xml","Group":"RIN... #hooks:0 2023-02-20 09:39:06.895 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.TransportState was: STOPPED now: TRANSITIONING #hooks:0 2023-02-20 09:39:06.901 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.CurrentPlayMode was: SHUFFLE_NOREPEAT now: NORMAL #hooks:0 2023-02-20 09:39:06.913 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.CurrentTransportActions was: Set, Stop, Pause, Play, X_DLNA_SeekTime, Next, X_DLNA_SeekTrackNr now: Set, Stop, Pause, Play, X_DLNA_SeekTime, X_DLNA_SeekTrackNr #hooks:0 2023-02-20 09:39:06.921 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.NumberOfTracks was: 10 now: 1 #hooks:0 2023-02-20 09:39:06.922 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.AVTransportURI was: x-rincon-queue:RINCON_000E58DC7BBE01400#0 now: http://redacted:3480/www/sounds/AllClosed.mp3 #hooks:0 2023-02-20 09:39:11.929 luup_log:214: Sonos: UPnP_request() "urn:schemas-upnp-org:service:AVTransport:1"#"GetPositionInfo" action took 5.0073010921478s (long) 2023-02-20 09:39:11.932 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.CurrentTrackDuration was: 0:02:22 now: 0:00:00 #hooks:0 2023-02-20 09:39:11.933 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.CurrentTrackURI was: x-file-cifs://ELEPHANT1/Multimedia/My%20Music/Music%20JP/The%20Smiths/The%20Queen%20Is%20Dead/08%20Vicar%20in%20a%2... now: http://redacted:3480/www/sounds/AllClosed.mp3 #hooks:0 2023-02-20 09:39:11.934 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.CurrentTrackMetaData was: <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:r... now: <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:r... #hooks:0 2023-02-20 09:39:11.936 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.CurrentStatus was: Vicar in a Tutu: (The Smiths, The Queen Is Dead) now: AllClosed.mp3 #hooks:0 2023-02-20 09:39:11.937 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.CurrentTitle was: Vicar in a Tutu now: AllClosed.mp3 #hooks:0 2023-02-20 09:39:11.937 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.CurrentArtist was: The Smiths now: #hooks:0 2023-02-20 09:39:11.938 luup.variable_set:: 217.urn:upnp-org:serviceId:AVTransport.CurrentAlbum was: The Queen Is Dead now: #hooks:0
Also see these:
2023-02-24 16:12:13.576 openLuup.server:: GET /www/sounds/YouRang.mp3 HTTP/1.1 tcp{client}: 0x17e96f0 2023-02-24 16:12:13.579 openLuup.server:: error 'closed' sending 43102 bytes to tcp{client}: 0x17e96f0
So any clues?
-
Well, clearly an HTTP request has not been completed. Has anything changed recently? A network change, perhaps. Software update? Not obvious why this is happening.
1/2