+- OpenHome Forum (http://forum.openhome.org)
+-- Forum: OpenHome (/forumdisplay.php?fid=1)
+--- Forum: Net (/forumdisplay.php?fid=5)
+--- Thread: [Solved] EventSessionUpnp::Run, ReaderError handling - Endless subscription loop (/showthread.php?tid=1548)
[Solved] EventSessionUpnp::Run, ReaderError handling - Endless subscription loop - ChriD - 17-11-2016 08:23 AM
Hi,
I created a application that on some specific network installations uses a lot of cpu in idle mode.
The UPNP Log looks like this:
Code:
2016.11.16 20:16:04.138 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0101-10E7-8001-14DDA9D3F5DE seq - 0
2016.11.16 20:16:04.140 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0001-10CD-8001-14DDA9D3F5DE seq - 0
2016.11.16 20:16:04.145 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0001-10E3-8001-14DDA9D3F5DE seq - 0
2016.11.16 20:16:04.145 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0102-10E8-8001-14DDA9D3F5DE seq - 0
2016.11.16 20:16:04.150 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0001-10CE-8001-14DDA9D3F5DE seq - 0
2016.11.16 20:16:04.152 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0102-10EA-8001-14DDA9D3F5DE seq - 0
2016.11.16 20:16:04.159 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0001-10EB-8001-14DDA9D3F5DE seq - 0
2016.11.16 20:16:04.160 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0001-10CF-8001-14DDA9D3F5DE seq - 0
...This goes on all the time (the same sid's will repeat about each 2 seconds) and seems to raise the CPU usage to 100% ???
Code:
2016.11.16 20:16:02.608 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0102-1076-8001-14DDA9D3F5DE seq - 0
2016.11.16 20:16:04.745 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0102-1076-8001-14DDA9D3F5DE seq - 0
2016.11.16 20:16:06.901 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0102-1076-8001-14DDA9D3F5DE seq - 0
2016.11.16 20:16:07.956 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0102-1076-8001-14DDA9D3F5DE seq - 0
...It looks like subscription can be done but then is some error and the service will be unsubscribed again only to be subscribed a view seconds later.
Of course if there are a plenty of those devices (which it seems to be in that case) the error raises every 2-3 miliseconds --> high cpu usage?
Code:
2016.11.16 20:32:37.669 DEBUG: UPNP: Subscription (0x7fda78011100) for 4D454930-0000-1000-8001-A813745D57A0, urn:schemas-upnp-org:service:ConnectionManager:1 completed
Sid is 4D454931-0001-103A-8001-14DDA9D3F5DE
Renew in 300 secs
2016.11.16 20:32:37.681 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0001-103A-8001-14DDA9D3F5DE seq - 0
2016.11.16 20:32:37.681 DEBUG: UPNP: Unsubscribing (0x7fda78011100) sid 4D454931-0001-103A-8001-14DDA9D3F5DE
2016.11.16 20:32:37.683 DEBUG: UPNP: Unsubscribed (0x7fda78011100) sid 4D454931-0001-103A-8001-14DDA9D3F5DE in 2ms
2016.11.16 20:32:42.168 DEBUG: UPNP: Subscription (0x7fda78011100) for 4D454930-0000-1000-8001-A813745D57A0, urn:schemas-upnp-org:service:ConnectionManager:1 completed
Sid is 4D454931-0001-103A-8001-14DDA9D3F5DE
Renew in 300 secs
2016.11.16 20:32:42.179 DEBUG: UPNP: EventSessionUpnp::Run, ReaderError handling sid - 4D454931-0001-103A-8001-14DDA9D3F5DE seq - 0
...Any Ideas what could be the problem?
BTW: What does the "sid's" representate? There seems to be hundred differents sids in the log
Thanks
RE: EventSessionUpnp::Run, ReaderError handling - Endless subscription loop - simonc - 21-11-2016 04:40 PM
I've seen this type of issue a couple of times previously. In these cases, a device on the network was sending an evented update that the control point viewed as invalid. When this happens, ohNet unsubscribes from the problem device/service then creates a new subscription.
Creating a new subscription is exactly the right thing to do in cases where a control point has missed one or more updates from a device. It's the wrong thing to do in cases where the device always sends invalid updates. Unfortunately ohNet does not currently distinguish between these two cases.
Assuming you have a test setup that demonstrates the problem fairly reliably, I'd add some custom logging to ohNet to print all HTTP traffic received by its UPnP eventing server. If you want to try this, add the line
Code:
LogVerbose(true);After this, rebuild ohNet then re-run your test. All UPnP eventing traffic will be logged to console (or wherever you have re-directed logging to). Look out for events from the device that fails and conpare them to UPnP/HTTP specs or events from devices that work.
RE: EventSessionUpnp::Run, ReaderError handling - Endless subscription loop - ChriD - 22-11-2016 08:36 AM
Okay, Thanks i will try!
It seems to be some Panasonic TV's have the problem. But i have to check which service of the tv makes the problem.
The Problem can be reproduced. If the TV's are on, there are the errors, If the TV's are off. The seems to be gone
But one question!
If i do not subscribe to those, maybe corrupt, services on the "tv's" the problem should be gone?
Thanks!
RE: EventSessionUpnp::Run, ReaderError handling - Endless subscription loop - simonc - 22-11-2016 08:45 AM
(22-11-2016 08:36 AM)ChriD Wrote: But one question!
If i do not subscribe to those, maybe corrupt, services on the "tv's" the problem should be gone?
Yes. Always assuming that the problem is related to bad initial events anyway...