Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[upnpcontrol] Device goes offline with device not registered error #16638

Open
mjcumming opened this issue Apr 11, 2024 · 17 comments · May be fixed by #17976
Open

[upnpcontrol] Device goes offline with device not registered error #16638

mjcumming opened this issue Apr 11, 2024 · 17 comments · May be fixed by #17976
Labels
bug An unexpected problem or unintended behavior of an add-on

Comments

@mjcumming
Copy link

mjcumming commented Apr 11, 2024 •
edited by lsiepel
Loading

I am openHAB 4.2.0-SNAPSHOT - Build #4031

When starting OpenHAB, the UPNP service connects to my UPNP player and works fine. After 20-30 minutes, the binding loses connection with the device with a "Device Not Registered" error. Trace level output is below. Output is from startup to connection lost. It looks like to me the discovery service (very.UpnpControlDiscoveryParticipant) is finding the device a second time which then cause the device to go offline with a device not registered error.

2024-04-11 05:31:00.285 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from UNINITIALIZED (NOT_YET_READY) to INITIALIZING
2024-04-11 05:31:00.299 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from INITIALIZING to UNKNOWN
2024-04-11 05:31:00.364 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from UNKNOWN to ONLINE
2024-04-11 05:31:00.561 [DEBUG] [ontrol.internal.util.UpnpControlUtil] - No .fav files in /var/lib/openhab/upnpcontrol/
2024-04-11 05:31:00.562 [DEBUG] [pnpDynamicCommandDescriptionProvider] - Adding command description for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:favoriteselect
2024-04-11 05:31:00.563 [DEBUG] [pnpDynamicCommandDescriptionProvider] - Adding command description for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:playlistselect
2024-04-11 05:31:00.565 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:00.566 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:00.568 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen add upnp subscription on AVTransport
2024-04-11 05:31:00.585 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen add upnp subscription on RenderingControl
2024-04-11 05:31:00.602 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action GetMute on service RenderingControl reply {}
2024-04-11 05:31:00.603 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action GetVolume on service RenderingControl with inputs {InstanceID=0, Channel=Single}
2024-04-11 05:31:00.639 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action GetVolume on service RenderingControl reply {CurrentVolume=22}
2024-04-11 05:31:00.640 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable SingleVolume with value 22 from service RenderingControl
2024-04-11 05:31:00.642 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action GetTransportInfo on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:31:00.677 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen received subscription reply true from service RenderingControl
2024-04-11 05:31:00.677 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action GetTransportInfo on service AVTransport reply {CurrentSpeed=1, CurrentTransportState=NO_MEDIA_PRESENT, CurrentTransportStatus=OK}
2024-04-11 05:31:00.678 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentSpeed with value 1 from service AVTransport
2024-04-11 05:31:00.679 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTransportState with value NO_MEDIA_PRESENT from service AVTransport
2024-04-11 05:31:00.681 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTransportStatus with value OK from service AVTransport
2024-04-11 05:31:00.686 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen received subscription reply true from service AVTransport
2024-04-11 05:31:00.707 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
2024-04-11 05:31:00.713 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/">
2024-04-11 05:31:00.720 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable InstanceID with value 0 from service RenderingControl
2024-04-11 05:31:00.721 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrackURI with value  from service AVTransport
2024-04-11 05:31:00.721 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable Channel with value 0 from service RenderingControl
2024-04-11 05:31:00.722 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable MasterMute with value 0 from service RenderingControl
2024-04-11 05:31:00.725 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable Equaluzer with value 0 from service RenderingControl
2024-04-11 05:31:00.723 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen received URI: 
2024-04-11 05:31:00.727 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable PresetNameList with value FactoryDefaults from service RenderingControl
2024-04-11 05:31:00.728 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable MasterVolume with value 22 from service RenderingControl
2024-04-11 05:31:00.731 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen current URI: , equal to received URI true
2024-04-11 05:31:00.732 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen next URI: 
2024-04-11 05:31:00.734 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable AbsoluteTimePosition with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 05:31:00.735 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable TransportPlaySpeed with value 1 from service AVTransport
2024-04-11 05:31:00.741 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable AbsoluteCounterPosition with value -1 from service AVTransport
2024-04-11 05:31:00.741 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrackURI with value  from service AVTransport
2024-04-11 05:31:00.743 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen received URI: 
2024-04-11 05:31:00.751 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen current URI: , equal to received URI true
2024-04-11 05:31:00.754 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen next URI: 
2024-04-11 05:31:00.755 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable InstanceID with value 0 from service AVTransport
2024-04-11 05:31:00.756 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrackMetaData with value  from service AVTransport
2024-04-11 05:31:00.776 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable RelativeTimePosition with value 00:00:00 from service AVTransport
2024-04-11 05:31:00.779 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable RelativeCounterPosition with value -1 from service AVTransport
2024-04-11 05:31:00.781 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable TransportStatus with value OK from service AVTransport
2024-04-11 05:31:00.782 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrackDuration with value 00:00:00 from service AVTransport
2024-04-11 05:31:00.790 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentPlayMode with value NORMAL from service AVTransport
2024-04-11 05:31:00.790 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable PossiblePlaybackStorageMedia with value NONE,STATION-NETWORK,SONGLIST-NETWORK,SONGLIST-LOCAL,SONGLIST-LOCAL_TF,THIRD-DLNA,AIRPLAY,UNKNOWN from service AVTransport
2024-04-11 05:31:00.792 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrack with value 0 from service AVTransport
2024-04-11 05:31:00.793 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentRecordQualityMode with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 05:31:00.794 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable RecordMediumWriteStatus with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 05:31:00.795 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable PlaybackStorageMedium with value NONE from service AVTransport
2024-04-11 05:31:00.796 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable PossibleRecordQualityModes with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 05:31:00.797 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTransportActions with value Play,Stop,Seek,X_DLNA_SeekTime,Pause from service AVTransport
2024-04-11 05:31:00.798 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable NumberOfTracks with value 0 from service AVTransport
2024-04-11 05:31:00.799 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable PossibleRecordStorageMedia with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 05:31:00.801 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentMediaDuration with value 00:00:00 from service AVTransport
2024-04-11 05:31:00.801 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable RecordStorageMedium with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 05:31:00.803 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable TransportState with value NO_MEDIA_PRESENT from service AVTransport
2024-04-11 05:31:01.700 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:01.701 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:01.703 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:01.703 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:01.704 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:01.704 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:01.705 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:01.703 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:01.705 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:01.706 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:01.707 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:01.708 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:01.708 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:01.708 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:01.709 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:01.708 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:01.710 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:01.711 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.333 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.333 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.334 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.334 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.334 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.335 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.334 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.339 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.342 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.342 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.343 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.343 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.343 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.343 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.384 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.385 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.726 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.726 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.726 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.727 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.727 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.727 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.730 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.731 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.732 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.731 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.735 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.735 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.738 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.736 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.740 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.737 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlevolume already exists
2024-04-11 05:31:02.742 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:31:02.742 [TRACE] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen, channel Singlemute already exists
2024-04-11 05:32:42.945 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command 32 for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:volume on renderer Arylic Kitchen
2024-04-11 05:32:42.946 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action SetVolume on service RenderingControl with inputs {InstanceID=0, Channel=Master, DesiredVolume=32}
2024-04-11 05:32:42.967 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action SetVolume on service RenderingControl reply {}
2024-04-11 05:34:04.850 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command PLAY for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:control on renderer Arylic Kitchen
2024-04-11 05:34:04.851 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}
2024-04-11 05:34:04.871 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Play on service AVTransport reply {}
2024-04-11 05:34:45.947 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command NEXT for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:control on renderer Arylic Kitchen
2024-04-11 05:34:45.948 [DEBUG] [internal.handler.UpnpRendererHandler] - Cannot serve next, end of queue on renderer Arylic Kitchen
2024-04-11 05:34:45.949 [TRACE] [internal.handler.UpnpRendererHandler] - Reset to start queue on renderer Arylic Kitchen
2024-04-11 05:34:45.949 [TRACE] [internal.handler.UpnpRendererHandler] - Reset queue, current queue index: -1
2024-04-11 05:34:45.949 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:34:45.973 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:34:56.597 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command PREVIOUS for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:control on renderer Arylic Kitchen
2024-04-11 05:34:56.598 [DEBUG] [internal.handler.UpnpRendererHandler] - Cannot serve previous, already at start of queue on renderer Arylic Kitchen
2024-04-11 05:34:56.598 [TRACE] [internal.handler.UpnpRendererHandler] - Reset to start queue on renderer Arylic Kitchen
2024-04-11 05:34:56.598 [TRACE] [internal.handler.UpnpRendererHandler] - Reset queue, current queue index: -1
2024-04-11 05:34:56.598 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:34:56.617 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:34:56.779 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command PREVIOUS for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:control on renderer Arylic Kitchen
2024-04-11 05:34:56.779 [DEBUG] [internal.handler.UpnpRendererHandler] - Cannot serve previous, already at start of queue on renderer Arylic Kitchen
2024-04-11 05:34:56.779 [TRACE] [internal.handler.UpnpRendererHandler] - Reset to start queue on renderer Arylic Kitchen
2024-04-11 05:34:56.780 [TRACE] [internal.handler.UpnpRendererHandler] - Reset queue, current queue index: -1
2024-04-11 05:34:56.780 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:34:56.798 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:34:56.921 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command PREVIOUS for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:control on renderer Arylic Kitchen
2024-04-11 05:34:56.922 [DEBUG] [internal.handler.UpnpRendererHandler] - Cannot serve previous, already at start of queue on renderer Arylic Kitchen
2024-04-11 05:34:56.922 [TRACE] [internal.handler.UpnpRendererHandler] - Reset to start queue on renderer Arylic Kitchen
2024-04-11 05:34:56.923 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:34:56.925 [TRACE] [internal.handler.UpnpRendererHandler] - Reset queue, current queue index: -1
2024-04-11 05:34:56.940 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:34:57.100 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command PREVIOUS for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:control on renderer Arylic Kitchen
2024-04-11 05:34:57.100 [DEBUG] [internal.handler.UpnpRendererHandler] - Cannot serve previous, already at start of queue on renderer Arylic Kitchen
2024-04-11 05:34:57.101 [TRACE] [internal.handler.UpnpRendererHandler] - Reset to start queue on renderer Arylic Kitchen
2024-04-11 05:34:57.101 [TRACE] [internal.handler.UpnpRendererHandler] - Reset queue, current queue index: -1
2024-04-11 05:34:57.101 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:34:57.117 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:35:11.094 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command PAUSE for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:control on renderer Arylic Kitchen
2024-04-11 05:35:11.097 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Pause on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:35:11.117 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Pause on service AVTransport reply {}
2024-04-11 05:36:05.869 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:mute on renderer Arylic Kitchen
2024-04-11 05:36:05.870 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action SetMute on service RenderingControl with inputs {InstanceID=0, Channel=Master, DesiredMute=1}
2024-04-11 05:36:05.892 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action SetMute on service RenderingControl reply {}
2024-04-11 05:36:07.232 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command OFF for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:mute on renderer Arylic Kitchen
2024-04-11 05:36:07.234 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action SetMute on service RenderingControl with inputs {InstanceID=0, Channel=Master, DesiredMute=0}
2024-04-11 05:36:07.259 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action SetMute on service RenderingControl reply {}
2024-04-11 05:50:18.589 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command PAUSE for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:control on renderer Arylic Kitchen
2024-04-11 05:50:18.594 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Pause on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:50:18.608 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:stop on renderer Arylic Kitchen
2024-04-11 05:50:18.617 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF31F09E-253B-7EF5-AF4E-0004FF31F09E:stop on renderer Arylic Dock
2024-04-11 05:50:18.620 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:50:18.621 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:50:18.631 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Pause on service AVTransport reply {}
2024-04-11 05:50:18.632 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:50:18.650 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:stop on renderer Arylic Kitchen
2024-04-11 05:50:18.654 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:50:18.654 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:50:18.657 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF31F09E-253B-7EF5-AF4E-0004FF31F09E:stop on renderer Arylic Dock
2024-04-11 05:50:18.660 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:50:18.661 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:50:18.673 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:50:20.759 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command PLAY for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:control on renderer Arylic Kitchen
2024-04-11 05:50:20.760 [TRACE] [internal.handler.UpnpRendererHandler] - Serve media on renderer Arylic Kitchen
2024-04-11 05:50:21.724 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command PAUSE for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:control on renderer Arylic Kitchen
2024-04-11 05:50:21.727 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Pause on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:50:21.741 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF31F09E-253B-7EF5-AF4E-0004FF31F09E:stop on renderer Arylic Dock
2024-04-11 05:50:21.741 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:stop on renderer Arylic Kitchen
2024-04-11 05:50:21.743 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:50:21.743 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:50:21.747 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Pause on service AVTransport reply {}
2024-04-11 05:50:21.747 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:50:21.763 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:50:41.858 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command PAUSE for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:control on renderer Arylic Kitchen
2024-04-11 05:50:41.861 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Pause on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:50:41.875 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF31F09E-253B-7EF5-AF4E-0004FF31F09E:stop on renderer Arylic Dock
2024-04-11 05:50:41.877 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:50:41.878 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport reply {}
2024-04-11 05:50:41.890 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:stop on renderer Arylic Kitchen
2024-04-11 05:50:41.891 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Pause on service AVTransport reply {}
2024-04-11 05:50:41.892 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 05:50:41.920 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport reply {}
2024-04-11 06:01:00.603 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen add upnp subscription on AVTransport
2024-04-11 06:01:00.608 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen add upnp subscription on RenderingControl
2024-04-11 06:01:00.633 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen received subscription reply true from service AVTransport
2024-04-11 06:01:00.649 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen received subscription reply true from service RenderingControl
2024-04-11 06:01:00.652 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
2024-04-11 06:01:00.658 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrackURI with value  from service AVTransport
2024-04-11 06:01:00.658 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/">
2024-04-11 06:01:00.661 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen received URI: 
2024-04-11 06:01:00.663 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen current URI: , equal to received URI true
2024-04-11 06:01:00.663 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable InstanceID with value 0 from service RenderingControl
2024-04-11 06:01:00.664 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable Channel with value 0 from service RenderingControl
2024-04-11 06:01:00.664 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen next URI: 
2024-04-11 06:01:00.665 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable MasterMute with value 0 from service RenderingControl
2024-04-11 06:01:00.665 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable AbsoluteTimePosition with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 06:01:00.665 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable TransportPlaySpeed with value 1 from service AVTransport
2024-04-11 06:01:00.666 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable Equaluzer with value 0 from service RenderingControl
2024-04-11 06:01:00.667 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable PresetNameList with value FactoryDefaults from service RenderingControl
2024-04-11 06:01:00.667 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable MasterVolume with value 32 from service RenderingControl
2024-04-11 06:01:00.668 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable AbsoluteCounterPosition with value -1 from service AVTransport
2024-04-11 06:01:00.669 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrackURI with value  from service AVTransport
2024-04-11 06:01:00.673 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen received URI: 
2024-04-11 06:01:00.675 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen current URI: , equal to received URI true
2024-04-11 06:01:00.675 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen next URI: 
2024-04-11 06:01:00.676 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable InstanceID with value 0 from service AVTransport
2024-04-11 06:01:00.677 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrackMetaData with value  from service AVTransport
2024-04-11 06:01:00.687 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable RelativeTimePosition with value 00:00:00 from service AVTransport
2024-04-11 06:01:00.689 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable RelativeCounterPosition with value -1 from service AVTransport
2024-04-11 06:01:00.690 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable TransportStatus with value OK from service AVTransport
2024-04-11 06:01:00.690 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrackDuration with value 00:00:00 from service AVTransport
2024-04-11 06:01:00.693 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentPlayMode with value NORMAL from service AVTransport
2024-04-11 06:01:00.694 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable PossiblePlaybackStorageMedia with value NONE,STATION-NETWORK,SONGLIST-NETWORK,SONGLIST-LOCAL,SONGLIST-LOCAL_TF,THIRD-DLNA,AIRPLAY,UNKNOWN from service AVTransport
2024-04-11 06:01:00.695 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrack with value 0 from service AVTransport
2024-04-11 06:01:00.696 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentRecordQualityMode with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 06:01:00.697 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable RecordMediumWriteStatus with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 06:01:00.698 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable PlaybackStorageMedium with value NONE from service AVTransport
2024-04-11 06:01:00.699 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable PossibleRecordQualityModes with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 06:01:00.700 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTransportActions with value Play,Stop,Seek,X_DLNA_SeekTime,Pause from service AVTransport
2024-04-11 06:01:00.701 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable NumberOfTracks with value 0 from service AVTransport
2024-04-11 06:01:00.702 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable PossibleRecordStorageMedia with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 06:01:00.703 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentMediaDuration with value 00:00:00 from service AVTransport
2024-04-11 06:01:00.703 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable RecordStorageMedium with value NOT_IMPLEMENTED from service AVTransport
2024-04-11 06:01:00.704 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable TransportState with value NO_MEDIA_PRESENT from service AVTransport
2024-04-11 06:01:00.725 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:stop on renderer Arylic Kitchen
2024-04-11 06:01:00.727 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 06:01:00.741 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport reply {}
2024-04-11 06:01:00.744 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF31F09E-253B-7EF5-AF4E-0004FF31F09E:stop on renderer Arylic Dock
2024-04-11 06:01:00.746 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 06:01:00.747 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport reply {}
2024-04-11 06:01:00.758 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF31F09E-253B-7EF5-AF4E-0004FF31F09E:stop on renderer Arylic Dock
2024-04-11 06:01:00.758 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D:stop on renderer Arylic Kitchen
2024-04-11 06:01:00.759 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 06:01:00.759 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Dock invoke upnp action Stop on service AVTransport reply {}
2024-04-11 06:01:00.761 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2024-04-11 06:01:00.776 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen invoke upnp action Stop on service AVTransport reply {}
2024-04-11 06:01:03.479 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type MediaRenderer, manufacturer Rakoit Technology(SZ) Co., Ltd., model H50, SN# 00001, UDN FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D
2024-04-11 06:01:03.480 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Media renderer found: Rakoit Technology(SZ) Co., Ltd., H50
2024-04-11 06:01:03.482 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen received status update false
2024-04-11 06:01:03.484 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication lost with Arylic Kitchen
2024-04-11 06:02:00.612 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from OFFLINE (COMMUNICATION_ERROR): Communication lost with Arylic Kitchen to OFFLINE (COMMUNICATION_ERROR): UPnP device with UDN FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D not yet registered
@mjcumming mjcumming added the bug An unexpected problem or unintended behavior of an add-on label Apr 11, 2024
@mjcumming
Copy link
Author

From my review of the code, we see a new device arrive via the output from UpnpControlDiscoveryParticipant.java and then a communication lost output from UpnpHandler.java at line 414. I am not a Java developer, so that's my best understanding of what is happening. Is it possible that the binding is trying to add a new thing when the thing already exists and that is what is causing the error?

@mjcumming
Copy link
Author

mjcumming commented Apr 13, 2024 •
edited by lsiepel
Loading

Here is the output after disabling and enabling the thing. If I restart openhab the device will come back online for awhile before seeing the error above.

2024-04-12 20:02:10.665 [DEBUG] [internal.handler.UpnpRendererHandler] - Disposing handler for media renderer device Arylic Kitchen
==> /var/log/openhab/events.log <==

2024-04-12 20:02:10.657 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from OFFLINE (COMMUNICATION_ERROR): UPnP device with UDN FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D not yet registered to UNINITIALIZED
2024-04-12 20:02:10.668 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'ArylicKitchenTrackposition' updated to 0 s
2024-04-12 20:02:10.669 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'ArylicKitchenReltrackposition' updated to 0
2024-04-12 20:02:10.670 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'ArylicKitchenControl' updated to PLAY
2024-04-12 20:02:10.670 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ArylicKitchenControl' changed from PAUSE to PLAY
2024-04-12 20:02:10.674 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'All_Music' received command ON
2024-04-12 20:02:10.675 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
2024-04-12 20:02:11.534 [DEBUG] [l.internal.UpnpControlHandlerFactory] - Media renderer handler created for Arylic Kitchen with UID upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D
2024-04-12 20:02:11.547 [DEBUG] [ontrol.internal.util.UpnpControlUtil] - No .lst files in /var/lib/openhab/upnpcontrol/
2024-04-12 20:02:11.548 [DEBUG] [pnpDynamicCommandDescriptionProvider] - Adding command description for channel upnpcontrol:upnprenderer:FF31F09E-7AAF-270E-A4C0-10F6FF31F09E:playlistselect
2024-04-12 20:02:11.548 [DEBUG] [pnpDynamicCommandDescriptionProvider] - Adding command description for channel upnpcontrol:upnprenderer:FF31F09E-253B-7EF5-AF4E-0004FF31F09E:playlistselect
2024-04-12 20:02:11.549 [DEBUG] [internal.handler.UpnpRendererHandler] - Initializing handler for media renderer device Arylic Kitchen

==> /var/log/openhab/events.log <==

2024-04-12 20:02:11.540 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from UNINITIALIZED (DISABLED) to INITIALIZING
2024-04-12 20:02:11.550 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from INITIALIZING to UNKNOWN
2024-04-12 20:02:11.550 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from UNKNOWN to OFFLINE (COMMUNICATION_ERROR): UPnP device with UDN FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D not yet

@jgeraerts
Copy link

Same problem here with my arylic devices. ( don't have any other so I don't know if its specific to arylic. ).

I've noticed openhab/jupnp responding with a http 501 on the call back urls:

NOTIFY /upnpcallback/dev/FF31F09E-3073-7678-CE68-98C0FF31F09E/svc/upnp-org/RenderingControl/event/cb HTTP/1.1
HOST: 172.16.1.6:8080
CONTENT-TYPE: text/xml; charset="utf-8"
CONTENT-LENGTH: 647
NT: upnp:event
NTS: upnp:propchange
SID: uuid:34c2b030-1dd2-11b2-b949-90aa2a4c549b
SEQ: 0

<?xml version='1.0' encoding='UTF-8' ?>
<e:propertyset xmlns:e="urn:schemas-upnp-org:event-1-0">
  <e:property>
    <LastChange>&lt;Event xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/RCS/&quot;&gt;
  &lt;InstanceID val=&quot;0&quot;&gt;
  &lt;Mute channel=&quot;Master&quot; val=&quot;0&quot;/&gt;
  &lt;Channel channel=&quot;Master&quot; val=&quot;0&quot;/&gt;
  &lt;Equaluzer channel=&quot;Master&quot; val=&quot;0&quot;/&gt;
  &lt;Volume channel=&quot;Master&quot; val=&quot;80&quot;/&gt;
  &lt;PresetNameList val=&quot;FactoryDefaults&quot;/&gt;
  &lt;/InstanceID&gt;
&lt;/Event&gt;</LastChange>
</e:property>
</e:propertyset>

HTTP/1.1 501 Not Implemented
Content-Length: 0
Server: Jetty(9.4.54.v20240208)

@jgeraerts
Copy link

Digging a bit further the registration times out.

2024-07-29 09:22:07.770 [TRACE] [org.jupnp.registry.Registry         ] - Maintaining registry...
2024-07-29 09:22:07.771 [TRACE] [org.jupnp.registry.Registry         ] - Device '(RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:FF31F09E-3073-7678-CE68-98C0FF31F09E, Descriptor: http://172.16.1.141:49152/description.xml, Root: true'
 expires in seconds: -1
2024-07-29 09:22:07.771 [TRACE] [org.jupnp.registry.Registry         ] - Device '(RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:001132a3-f7df-0011-dff7-dff7a3321100, Descriptor: http://172.16.1.171:50001/desc/device.xml, Root: true'
 expires in seconds: 1657
2024-07-29 09:22:07.772 [TRACE] [org.jupnp.registry.Registry         ] - Device '(RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:FF31F09E-DDF8-82A3-EB48-917FFF31F09E, Descriptor: http://172.16.1.192:49152/description.xml, Root: true'
 expires in seconds: -1
2024-07-29 09:22:07.772 [TRACE] [org.jupnp.registry.Registry         ] - Device '(RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:RINCON_347E5CC5F52E01400, Descriptor: http://172.16.1.110:1400/xml/device_description.xml, Root: true' e
xpires in seconds: 1601
2024-07-29 09:22:07.773 [TRACE] [org.jupnp.registry.Registry         ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:FF31F09E-3073-7678-CE68-98C0FF31F09E, Descriptor: http://172.16.1.141:49152/description.xml, R
oot: true
2024-07-29 09:22:07.773 [TRACE] [org.jupnp.registry.Registry         ] - Removing remote device from registry: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:FF31F09E-3073-7678-CE68-98C0FF31F09E, Descriptor: http://172.16.1.141:4915
2/description.xml, Root: true
2024-07-29 09:22:07.774 [TRACE] [org.jupnp.model.Namespace           ] - Discovering local resources of device graph
2024-07-29 09:22:07.777 [TRACE] [org.jupnp.model.Namespace           ] - Discovered: (ServiceEventCallbackResource) URI: /upnpcallback/dev/FF31F09E-3073-7678-CE68-98C0FF31F09E/svc/upnp-org/AVTransport/event/cb
2024-07-29 09:22:07.778 [TRACE] [org.jupnp.model.Namespace           ] - Discovered: (ServiceEventCallbackResource) URI: /upnpcallback/dev/FF31F09E-3073-7678-CE68-98C0FF31F09E/svc/upnp-org/ConnectionManager/event/cb
2024-07-29 09:22:07.778 [TRACE] [org.jupnp.model.Namespace           ] - Discovered: (ServiceEventCallbackResource) URI: /upnpcallback/dev/FF31F09E-3073-7678-CE68-98C0FF31F09E/svc/upnp-org/RenderingControl/event/cb
2024-07-29 09:22:07.779 [TRACE] [org.jupnp.model.Namespace           ] - Discovered: (ServiceEventCallbackResource) URI: /upnpcallback/dev/FF31F09E-3073-7678-CE68-98C0FF31F09E/svc/wiimu-com/PlayQueue/event/cb
2024-07-29 09:22:07.779 [TRACE] [org.jupnp.model.Namespace           ] - Discovered: (ServiceEventCallbackResource) URI: /upnpcallback/dev/FF31F09E-3073-7678-CE68-98C0FF31F09E/svc/tencent-com/QPlay/event/cb
2024-07-29 09:22:07.779 [TRACE] [org.jupnp.registry.Registry         ] - Unregistered resource: (ServiceEventCallbackResource) URI: /upnpcallback/dev/FF31F09E-3073-7678-CE68-98C0FF31F09E/svc/upnp-org/AVTransport/event/cb
2024-07-29 09:22:07.779 [TRACE] [org.jupnp.registry.Registry         ] - Unregistered resource: (ServiceEventCallbackResource) URI: /upnpcallback/dev/FF31F09E-3073-7678-CE68-98C0FF31F09E/svc/upnp-org/ConnectionManager/event/cb
2024-07-29 09:22:07.779 [TRACE] [org.jupnp.registry.Registry         ] - Unregistered resource: (ServiceEventCallbackResource) URI: /upnpcallback/dev/FF31F09E-3073-7678-CE68-98C0FF31F09E/svc/upnp-org/RenderingControl/event/cb
2024-07-29 09:22:07.780 [TRACE] [org.jupnp.registry.Registry         ] - Unregistered resource: (ServiceEventCallbackResource) URI: /upnpcallback/dev/FF31F09E-3073-7678-CE68-98C0FF31F09E/svc/wiimu-com/PlayQueue/event/cb
2024-07-29 09:22:07.780 [TRACE] [org.jupnp.registry.Registry         ] - Unregistered resource: (ServiceEventCallbackResource) URI: /upnpcallback/dev/FF31F09E-3073-7678-CE68-98C0FF31F09E/svc/tencent-com/QPlay/event/cb
2024-07-29 09:22:07.780 [TRACE] [org.jupnp.registry.Registry         ] - Removing outgoing subscription: uuid:4264573e-1dd2-11b2-a85b-c206d5dac96a
2024-07-29 09:22:07.780 [TRACE] [org.jupnp.registry.Registry         ] - Removing outgoing subscription: uuid:4262c28e-1dd2-11b2-a85b-c206d5dac96a
2024-07-29 09:22:07.780 [DEBUG] [np.controlpoint.SubscriptionCallback] - A GENA subscription 'RenderingControl' for device 'uuid:FF31F09E-3073-7678-CE68-98C0FF31F09E' was ended
2024-07-29 09:22:07.782 [DEBUG] [np.controlpoint.SubscriptionCallback] - A GENA subscription 'AVTransport' for device 'uuid:FF31F09E-3073-7678-CE68-98C0FF31F09E' was ended

https://www.jupnp.org/docs/advanced#maximum-age-of-remote-devices seems relevant. Looking at https://github.com/jupnp/jupnp/blob/a623216048d60e02d0b9f8d3e68f47c7c69a8432/bundles/org.jupnp/src/main/java/org/jupnp/OSGiUpnpServiceConfiguration.java#L322C20-L322C48 this method returns null which means to trust the device's timeout. However I don't see the arylic device sending any alive messages.

@mjcumming
Copy link
Author

Interesting observations. Certainly fits with what I am seeing. When I restart this bundle openHAB Core :: Bundles :: Configuration jUPnP from the console, the devices come back on line.

@jgeraerts
Copy link

Yes, as a workaround i have now a curl script in a cronjob that triggers a scan every 15 minutes.

curl --silent -k -XPOST -H"Authorization: Bearer $APIKEYGOESHERE" https://$ip:8443/rest/discovery/bindings/upnpcontrol/scan

Potentionally this could also be the fix, to issue a search request from the binding.

@lsiepel
Copy link
Contributor

lsiepel commented Nov 10, 2024

Not that familiar with the upnp protocol. But this sounds like a specific issue with theses devices. Do you consider this a bug in the binding or in the device's handling?
Performing scheduled scans just to keep the device's connection alive sounds hackish, and also affects all other devices that do not need this.

Also don;t understand why the device goes offline as the active and the newly discovered device are the same device with the same UDN. The representation proeprty is properly set, so for openHAB concerns they are the same device.

@digitaldan
Copy link
Contributor

I just picked up a few WiiM streamers, which are manufactured directly by LinkPlay. They OEMs their hardware / software to other companies, including Arylic, the device @mjcumming is having issues with ( i think) . I am also facing the same issue, so its likely related to this vendor. i'll look into a fix for this.

@digitaldan
Copy link
Contributor

digitaldan commented Dec 23, 2024 •
edited
Loading

So also something interesting, i'm seeing NoRouteToHostException exceptions in the jupnp library to my device, but i can curl that URL fine from the openHAB host with no delay, i'm not sure why this is failing ? Very Strange.

2024-12-23 14:08:35.379 [WARN ] [org.jupnp.transport.spi.StreamClient] - HTTP request failed: (StreamRequestMessage) GET http://192.168.91.217:49152/description.xml
java.net.NoRouteToHostException: No route to host
	at sun.nio.ch.Net.pollConnect(Native Method) ~[?:?]
	at sun.nio.ch.Net.pollConnectNow(Net.java:672) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:946) ~[?:?]
	at org.eclipse.jetty.io.SelectorManager.doFinishConnect(SelectorManager.java:355) ~[?:?]
	at org.eclipse.jetty.io.ManagedSelector.processConnect(ManagedSelector.java:347) ~[?:?]
	at org.eclipse.jetty.io.ManagedSelector.access$1700(ManagedSelector.java:65) ~[?:?]
	at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.processSelected(ManagedSelector.java:676) ~[?:?]
	at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:535) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:362) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:186) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[?:?]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[?:?]
	at java.lang.Thread.run(Thread.java:840) [?:?]

@digitaldan
Copy link
Contributor

I think i have a fix built against 4.3.1 if people want to try it out, my device has been online for about an hour so far.

https://github.com/digitaldan/openhab-addons/releases/tag/upnp-keep-alive

See:

https://github.com/digitaldan/openhab-addons/blob/7df7ae68f20544be318ee74fd15fa6b242485243/bundles/org.openhab.binding.upnpcontrol/src/main/java/org/openhab/binding/upnpcontrol/internal/handler/UpnpHandler.java#L665-L681

@jgeraerts
Copy link

I'm testing it

@digitaldan
Copy link
Contributor

Mine stayed online over night 👍

@digitaldan digitaldan mentioned this issue Dec 24, 2024
Merged
@mherwege
Copy link
Contributor

@digitaldan Great you have been able to solve this. I assume you will create a PR.

@digitaldan
Copy link
Contributor

I will, was just waiting to confirm it works.

@digitaldan digitaldan linked a pull request Dec 24, 2024 that will close this issue
Open
@jgeraerts
Copy link

Here it went down unfortunately. Also no route to host. Will try to debug it after Christmas. Happy holidays nonetheless :)

@digitaldan
Copy link
Contributor

Also no route to host

So i only saw that the one time, not sure if its relevant or not. The good news is my device has not gone offline once yet, so definite improvement.

@jgeraerts
Copy link

Since the initial failure it has been up as well. So definitely an improvement.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug An unexpected problem or unintended behavior of an add-on
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

[upnpcontrol] Send periodic keep alive digitaldan/openhab-addons
5 participants
@jgeraerts @mjcumming @digitaldan @lsiepel @mherwege