UI issue: Intermittent initialization failed player error

[storaid]

Hi, Tiki

I sometimes encounter this strange error..

2024/10/05 17:09:06,150.327: T0b7b8: Error: UPnP_P: [SOAP Request]: Cannot connect to server: 10.1.1.97 :49152
2024/10/05 17:09:06,150.349: T0b7b8: Error: UPnP_P: [SOAP Request]: SOAP request: [GetVolume ] was failed.
2024/10/05 17:09:06,150.356: T0b7b8: Error: UPnP_P: [SOAP Request]: SOAP request detected error: [ 4] (TFXFWTimeout)
2024/10/05 17:09:06,150.447: T0b7b8: UPnP_P: [UPP_WorkerThread]: UnsubscribeAllEvent.
2024/10/05 17:09:06,150.487: T0b7b8: Subscriber: [UPP_WorkerThread]: UnsubscribeEvent: 10.1.1.97 [http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/evt-urn-schemas-upnp-org-service-AVTransport-1]
2024/10/05 17:09:09,164.218: T0b7b8: Subscriber: [UPP_WorkerThread]: - Server seems dead: 10.1.1.97
2024/10/05 17:09:09,164.250: T0b7b8: Subscriber: [UPP_WorkerThread]: UnsubscribeEvent: 10.1.1.97 [http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/evt-urn-schemas-upnp-org-service-ConnectionManager-1]
2024/10/05 17:09:09,164.554: T0b7b8: Subscriber: [UPP_WorkerThread]: - Server deemed dead: 10.1.1.97
2024/10/05 17:09:09,164.571: T0b7b8: Subscriber: [UPP_WorkerThread]: UnsubscribeEvent: 10.1.1.97 [http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/evt-urn-schemas-upnp-org-service-RenderingControl-1]
2024/10/05 17:09:09,164.716: T0b7b8: Subscriber: [UPP_WorkerThread]: - Server deemed dead: 10.1.1.97
2024/10/05 17:09:09,164.752: T0b7b8: UPnP_P: [UPP_WorkerThread]: Phase 1.
2024/10/05 17:09:09,664.748: T0b7b8: UPnP_P: [UPP_InitDevice1] 2: Initialize UPnP info of the Player.
2024/10/05 17:09:09,664.771: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP is initialized.
2024/10/05 17:09:09,664.785: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP DeviceInfo: USN:[uuid:87f1e18e-7e24-b992-8383-d83adde83eaf::urn:schemas-upnp-org:device:MediaRenderer:1]
2024/10/05 17:09:09,664.797: T0b7b8: UPnP_P: [UPP_InitDevice1] - Location: http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/description.xml
2024/10/05 17:09:09,664.806: T0b7b8: UPnP_P: [UPP_InitDevice1] - Name : Red_10.1.1.97-UPnP/AV
2024/10/05 17:09:09,664.815: T0b7b8: UPnP_P: [UPP_InitDevice1] - Model : UpMPD
2024/10/05 17:09:09,664.828: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP Service found: [urn:schemas-upnp-org:service:ConnectionManager:1]
2024/10/05 17:09:09,664.836: T0b7b8: UPnP_P: [UPP_InitDevice1] QuerySOAP: Getting ProtocolInfo.
2024/10/05 17:09:09,665.313: T0b7b8: UPnP_P: [SOAP Request]: SOAP request: [GetProtocolInfo ] to: 10.1.1.97 [http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/ctl-urn-schemas-upnp-org-service-ConnectionManager-1]
2024/10/05 17:09:12,677.949: T0b7b8: Error: UPnP_P: [SOAP Request]: Cannot connect to server: 10.1.1.97 :49152
2024/10/05 17:09:12,677.970: T0b7b8: Error: UPnP_P: [SOAP Request]: SOAP request: [GetProtocolInfo ] was failed.
2024/10/05 17:09:12,677.979: T0b7b8: Error: UPnP_P: [SOAP Request]: SOAP request detected error: [ 4] (TFXFWTimeout)
2024/10/05 17:09:12,678.005: T0b7b8: Error: UPnP_P: [UPP_InitDevice1] GetProtocolInfo failed.

You can see the connection failure issue in the log above…

Even so, TuneBrowser eventually manages to connect to the UPnP Renderer successfully.

Apparently, it has a retry feature.

Could the error message only appear after the retry limit is reached?

I think displaying this message prematurely might cause confusion…

Thanks

[Tiki]

It seems that SOAP call is failing. Then it is an error. There is no retry for SOAP call. I think it just succeeds on the next SOAP call.

[storaid]

Hi, Tiki,

Sorry, I may not have explained clearly enough.

2024/10/05 17:09:09,164: UL13826: T0b7b8: UPnP_P: [UPP_WorkerThread]: Phase 1.
2024/10/05 17:09:09,664: UL13828: T0b7b8: UPnP_P: [UPP_InitDevice1] 2: Initialize UPnP info of the Player.
2024/10/05 17:09:09,664: UL13830: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP is initialized.
2024/10/05 17:09:09,664: UL13832: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP DeviceInfo: USN:[uuid:87f1e18e-7e24-b992-8383-d83adde83eaf::urn:schemas-upnp-org:device:MediaRenderer:1]
2024/10/05 17:09:09,664: UL13834: T0b7b8: UPnP_P: [UPP_InitDevice1] - Location: http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/description.xml
2024/10/05 17:09:09,664: UL13836: T0b7b8: UPnP_P: [UPP_InitDevice1] - Name : Red_10.1.1.97-UPnP/AV
2024/10/05 17:09:09,664: UL13838: T0b7b8: UPnP_P: [UPP_InitDevice1] - Model : UpMPD
2024/10/05 17:09:09,664: UL13840: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP Service found: [urn:schemas-upnp-org:service:ConnectionManager:1]
2024/10/05 17:09:09,664: UL13842: T0b7b8: UPnP_P: [UPP_InitDevice1] QuerySOAP: Getting ProtocolInfo.
2024/10/05 17:09:09,665: UL13844: T0b7b8: UPnP_P: [SOAP Request]: SOAP request: [GetProtocolInfo ] to: 10.1.1.97 [http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/ctl-urn-schemas-upnp-org-service-ConnectionManager-1]
2024/10/05 17:09:12,677: UL13868: T0b7b8: Error: UPnP_P: [SOAP Request]: Cannot connect to server: 10.1.1.97 :49152
2024/10/05 17:09:12,677: UL13870: T0b7b8: Error: UPnP_P: [SOAP Request]: SOAP request: [GetProtocolInfo ] was failed.
2024/10/05 17:09:12,677: UL13872: T0b7b8: Error: UPnP_P: [SOAP Request]: SOAP request detected error: [ 4] (TFXFWTimeout)
2024/10/05 17:09:12,678: UL13874: T0b7b8: Error: UPnP_P: [UPP_InitDevice1] GetProtocolInfo failed.
2024/10/05 17:09:12,778: UL13877: T0b7b8: UPnP_P: [UPP_InitDevice1] 3: Initialize UPnP info of the Player.
2024/10/05 17:09:12,778: UL13879: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP is initialized.
2024/10/05 17:09:12,778: UL13881: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP DeviceInfo: USN:[uuid:87f1e18e-7e24-b992-8383-d83adde83eaf::urn:schemas-upnp-org:device:MediaRenderer:1]
2024/10/05 17:09:12,778: UL13883: T0b7b8: UPnP_P: [UPP_InitDevice1] - Location: http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/description.xml
2024/10/05 17:09:12,778: UL13885: T0b7b8: UPnP_P: [UPP_InitDevice1] - Name : Red_10.1.1.97-UPnP/AV
2024/10/05 17:09:12,778: UL13887: T0b7b8: UPnP_P: [UPP_InitDevice1] - Model : UpMPD
2024/10/05 17:09:12,778: UL13889: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP Service found: [urn:schemas-upnp-org:service:ConnectionManager:1]
2024/10/05 17:09:12,778: UL13891: T0b7b8: UPnP_P: [UPP_InitDevice1] QuerySOAP: Getting ProtocolInfo.
2024/10/05 17:09:12,779: UL13893: T0b7b8: UPnP_P: [SOAP Request]: SOAP request: [GetProtocolInfo ] to: 10.1.1.97 [http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/ctl-urn-schemas-upnp-org-service-ConnectionManager-1]
2024/10/05 17:09:15,794: UL13895: T0b7b8: Error: UPnP_P: [SOAP Request]: Cannot connect to server: 10.1.1.97 :49152
2024/10/05 17:09:15,794: UL13897: T0b7b8: Error: UPnP_P: [SOAP Request]: SOAP request: [GetProtocolInfo ] was failed.
2024/10/05 17:09:15,794: UL13899: T0b7b8: Error: UPnP_P: [SOAP Request]: SOAP request detected error: [ 4] (TFXFWTimeout)
2024/10/05 17:09:15,794: UL13901: T0b7b8: Error: UPnP_P: [UPP_InitDevice1] GetProtocolInfo failed.
2024/10/05 17:09:15,894: UL13903: T0b7b8: UPnP_P: [UPP_InitDevice1] 4: Initialize UPnP info of the Player.
2024/10/05 17:09:15,894: UL13905: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP is initialized.
2024/10/05 17:09:15,894: UL13907: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP DeviceInfo: USN:[uuid:87f1e18e-7e24-b992-8383-d83adde83eaf::urn:schemas-upnp-org:device:MediaRenderer:1]
2024/10/05 17:09:15,894: UL13909: T0b7b8: UPnP_P: [UPP_InitDevice1] - Location: http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/description.xml
2024/10/05 17:09:15,894: UL13911: T0b7b8: UPnP_P: [UPP_InitDevice1] - Name : Red_10.1.1.97-UPnP/AV
2024/10/05 17:09:15,894: UL13913: T0b7b8: UPnP_P: [UPP_InitDevice1] - Model : UpMPD
2024/10/05 17:09:15,894: UL13915: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP Service found: [urn:schemas-upnp-org:service:ConnectionManager:1]
2024/10/05 17:09:15,894: UL13917: T0b7b8: UPnP_P: [UPP_InitDevice1] QuerySOAP: Getting ProtocolInfo.
2024/10/05 17:09:15,895: UL13919: T0b7b8: UPnP_P: [SOAP Request]: SOAP request: [GetProtocolInfo ] to: 10.1.1.97 [http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/ctl-urn-schemas-upnp-org-service-ConnectionManager-1]
2024/10/05 17:09:18,905: UL13922: T0b7b8: Error: UPnP_P: [SOAP Request]: Cannot connect to server: 10.1.1.97 :49152
2024/10/05 17:09:18,905: UL13924: T0b7b8: Error: UPnP_P: [SOAP Request]: SOAP request: [GetProtocolInfo ] was failed.
2024/10/05 17:09:18,905: UL13926: T0b7b8: Error: UPnP_P: [SOAP Request]: SOAP request detected error: [ 4] (TFXFWTimeout)
2024/10/05 17:09:18,906: UL13928: T0b7b8: Error: UPnP_P: [UPP_InitDevice1] GetProtocolInfo failed.
2024/10/05 17:09:19,006: UL13930: T0b7b8: UPnP_P: [UPP_InitDevice1] 5: Initialize UPnP info of the Player.
2024/10/05 17:09:19,006: UL13932: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP is initialized.
2024/10/05 17:09:19,006: UL13934: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP DeviceInfo: USN:[uuid:87f1e18e-7e24-b992-8383-d83adde83eaf::urn:schemas-upnp-org:device:MediaRenderer:1]
2024/10/05 17:09:19,006: UL13936: T0b7b8: UPnP_P: [UPP_InitDevice1] - Location: http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/description.xml
2024/10/05 17:09:19,006: UL13938: T0b7b8: UPnP_P: [UPP_InitDevice1] - Name : Red_10.1.1.97-UPnP/AV
2024/10/05 17:09:19,006: UL13940: T0b7b8: UPnP_P: [UPP_InitDevice1] - Model : UpMPD
2024/10/05 17:09:19,006: UL13942: T0b7b8: UPnP_P: [UPP_InitDevice1] - UPnP Service found: [urn:schemas-upnp-org:service:ConnectionManager:1]
2024/10/05 17:09:19,006: UL13944: T0b7b8: UPnP_P: [UPP_InitDevice1] QuerySOAP: Getting ProtocolInfo.
2024/10/05 17:09:19,010: UL13946: T0b7b8: UPnP_P: [SOAP Request]: SOAP request: [GetProtocolInfo ] to: 10.1.1.97 [http://10.1.1.97:49152/uuid-87f1e18e-7e24-b992-8383-d83adde83eaf/ctl-urn-schemas-upnp-org-service-ConnectionManager-1]
2024/10/05 17:09:22,544: UL13951: T0b7b8: UPnP_P: [SOAP Request]: SOAP request: [GetProtocolInfo ] finished.

From the log, it looks very similar to a retry operation.

However, my key point is that unless the connection completely fails,

I think the following error message should not appear, as it might cause confusion…

[Tiki]

In this case, logs show that initializing is continuing. There is no reason to stop the initialization other than to exit TuneBrowser or change the playback device.

An error in GetProtocolInfo means that the SOAP call has failed after SSDP has confirmed that the device is alive, so it is judged to be an error.

I understand your feeling that the error message is annoying, but I think the device is actually behaving strangely, and since other users may not be the ones looking at the logs as you are, TuneBrowser is notifying you of the situation.

[storaid]

Hi, Tiki

If the log isn’t checked, seeing an error message pop-up in the UI might cause some misunderstanding, since the device might eventually connect successfully.

Therefore, I think the error message pop-up should be suppressed in the UI unless the device completely fails to connect.

Thanks

[Tiki]

I’ll make the timeout value adjustable in the next release. If the timeout is extended, the error will probably not be detected in your case.

[投稿者]

投稿