WEMO Binding - Invalid subscription ID, no active subscription

Add-ons Bindings
, ,
1

I repeatedly get error messages in the log from WEMO devices, is there a way to fix the problem, or turn off the errors if they are spurious? I’m running OH 2.1, I get 2 slightly different errors, and both of my WEMO Insights have them, sample of both messages below:

[ERROR] [g.jupnp.protocol.sync.ReceivingEvent] - Invalid subscription ID, no active subscription: (IncomingEventRequestMessage) NOTIFY /upnpcallback/dev/Insight-1_0-xxxxxxxxxxxx1/svc/Belkin/insight1/event/cb SEQUENCE: 148
[ERROR] [g.jupnp.protocol.sync.ReceivingEvent] - Invalid subscription ID, no active subscription: (IncomingEventRequestMessage) NOTIFY /upnpcallback/dev/Insight-1_0-xxxxxxxxxxxx2/svc/Belkin/basicevent1/event/cb SEQUENCE: 0

The errors seem to occur sporadically with no obvious pattern other than they are over 30 minutes between each device throwing an error. Rebooting the Pi doesn’t make them disappear.

@hmerk can you help me with this please?

2

This can happen to all UPnP enabled devices, so nothing WeMo specific.

You can use

log:set org.jupnp

on karaf console to stop logging these errors.

3

Thanks for the reply, I entered that and got

Error executing command: No enum constant org.apache.karaf.log.core.Level.ORG.JUPNP

Should I put a line in userdata/etc/org.ops4j.pax.logging.cfg, and if I should what should it be?

4

Sorry, my fault. Please try

log:set DEFAULT org.jupnp
5

That command seems to have worked, presumably it survives between reboots?

6

Not shure if it survives, but you can edit loggin as described here

7

It does survive.
log:set commands issued in the console get written in the last part of the org.ops4j.pax.logging.cfg file (in the # OSGi appender section)

1 Like
8

@hmerk adding the log command has had the opposite effect, my log is now filled with the messages at the bottom of this post, one for each of my wemo’s and occurring every 2-4 minutes
@Dim fortunately the log settings weren’t persistent, and there was no evidence of them in /var/lib/openhab2/etc/org.ops4j.pax.logging.cfg so a reboot reverted things back to the original messages in post 1

Suggestions?

2017-09-06 18:52:28.501 [WARN ] [org.jupnp.transport.spi.StreamClient] - HTTP request failed: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.38:49153/upnp/event/insight1
org.apache.http.NoHttpResponseException: The target server failed to respond
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)[35:org.apache.httpcomponents.httpclient:4.2.3]
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)[35:org.apache.httpcomponents.httpclient:4.2.3]
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)[36:org.apache.httpcomponents.httpcore:4.2.3]
at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)[36:org.apache.httpcomponents.httpcore:4.2.3]
at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)[35:org.apache.httpcomponents.httpclient:4.2.3]
at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)[35:org.apache.httpcomponents.httpclient:4.2.3]
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)[36:org.apache.httpcomponents.httpcore:4.2.3]
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)[36:org.apache.httpcomponents.httpcore:4.2.3]
at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)[35:org.apache.httpcomponents.httpclient:4.2.3]
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)[35:org.apache.httpcomponents.httpclient:4.2.3]
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)[35:org.apache.httpcomponents.httpclient:4.2.3]
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:1066)[35:org.apache.httpcomponents.httpclient:4.2.3]
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:1044)[35:org.apache.httpcomponents.httpclient:4.2.3]
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:1035)[35:org.apache.httpcomponents.httpclient:4.2.3]
at org.jupnp.transport.impl.apache.StreamClientImpl$4.call(StreamClientImpl.java:168)[162:org.jupnp:2.2.0]
at org.jupnp.transport.impl.apache.StreamClientImpl$4.call(StreamClientImpl.java:1)[162:org.jupnp:2.2.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_131]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_131]
9

Same here. After executing the command, also after reboot I still have a lot of warnings:

20:40:03.261 [WARN ] [org.jupnp.transport.spi.StreamClient ] - HTTP request failed: (StreamRequestMessage) GET http://192.168.XX.XX:1400/xml/group_description.xml (HttpConnectionOverHTTP@1c31308(l:/192.168.XX.XX:48400 ↔ r:/192.168.XX.XX:1400,closed=false)[HttpChannelOverHTTP@1742085(exchange=HttpExchange@76c011 req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@99dcb6(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@1bfc4be{s=START}],recv=HttpReceiverOverHTTP@17ba3c4(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of 0}]]])
20:40:03.319 [WARN ] [np.protocol.RetrieveRemoteDescriptors] - Device descriptor retrieval failed, no response: http://192.168.XX.XX:1400/xml/group_description.xml
20:40:05.812 [WARN ] [org.jupnp.transport.spi.StreamClient ] - HTTP request failed: (StreamRequestMessage) GET http://192.168.XX.XX:1400/xml/ZoneGroupTopology1.xml (HttpConnectionOverHTTP@1879a1e(l:/192.168.XX.XX:48407 ↔ r:/192.168.XX.XX:1400,closed=false)[HttpChannelOverHTTP@1c2324(exchange=HttpExchange@efd2e0 req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@1b2c34b(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@64f2c9{s=START}],recv=HttpReceiverOverHTTP@13ce822(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of 0}]]])
20:40:05.873 [WARN ] [np.protocol.RetrieveRemoteDescriptors] - Could not retrieve service descriptor, no response: (RemoteService) Descriptor: /xml/ZoneGroupTopology1.xml
20:40:05.981 [WARN ] [org.jupnp.transport.spi.StreamClient ] - HTTP request failed: (StreamRequestMessage) GET http://192.168.XX.XX:1400/xml/RenderingControl1.xml (HttpConnectionOverHTTP@1511df0(l:/192.168.XX.XX:48410 ↔ r:/192.168.XX.XX:1400,closed=false)[HttpChannelOverHTTP@971a71(exchange=HttpExchange@96b850 req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@193f245(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@f6cbda{s=START}],recv=HttpReceiverOverHTTP@741ca7(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of 0}]]])
20:40:06.041 [WARN ] [np.protocol.RetrieveRemoteDescriptors] - Could not retrieve service descriptor, no response: (RemoteService) Descriptor: /xml/RenderingControl1.xml
20:40:06.063 [WARN ] [np.protocol.RetrieveRemoteDescriptors] - Device service description failed: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:RINCON_5CAAFD41038C01400, Descriptor: http://192.168.XX.XX:1400/xml/device_description.xml, Root: true
20:40:22.519 [WARN ] [org.jupnp.transport.spi.StreamClient ] - HTTP request failed: (StreamRequestMessage) GET http://192.168.XX.XX:1400/xml/group_description.xml (HttpConnectionOverHTTP@497b45(l:/192.168.XX.XX:60814 ↔ r:/192.168.XX.XX:1400,closed=false)[HttpChannelOverHTTP@17a30ff(exchange=HttpExchange@15baeca req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@8de83b(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@14b35fc{s=START}],recv=HttpReceiverOverHTTP@1b817a2(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of 0}]]])
20:40:22.578 [WARN ] [np.protocol.RetrieveRemoteDescriptors] - Device descriptor retrieval failed, no response: http://192.168.XX.XX:1400/xml/group_description.xml
20:40:26.752 [WARN ] [org.jupnp.transport.spi.StreamClient ] - HTTP request failed: (StreamRequestMessage) GET http://192.168.XX.XX:1400/xml/SystemProperties1.xml (HttpConnectionOverHTTP@863353(l:/192.168.XX.XX:60819 ↔ r:/192.168.XX.XX:1400,closed=false)[HttpChannelOverHTTP@800f2a(exchange=HttpExchange@1f01c9f req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@1f83da(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@1583d21{s=START}],recv=HttpReceiverOverHTTP@129993f(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of 0}]]])
20:40:26.818 [WARN ] [np.protocol.RetrieveRemoteDescriptors] - Could not retrieve service descriptor, no response: (RemoteService) Descriptor: /xml/SystemProperties1.xml
20:40:26.862 [WARN ] [org.jupnp.transport.spi.StreamClient ] - HTTP request failed: (StreamRequestMessage) GET http://192.168.XX.XX:1400/xml/ZoneGroupTopology1.xml (HttpConnectionOverHTTP@1e008d6(l:/192.168.XX.XX:60821 ↔ r:/192.168.XX.XX:1400,closed=false)[HttpChannelOverHTTP@11ba929(exchange=HttpExchange@16626ea req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@1d9ed5f(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@dceaca{s=START}],recv=HttpReceiverOverHTTP@9a5499(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of 0}]]])
20:40:26.922 [WARN ] [np.protocol.RetrieveRemoteDescriptors] - Could not retrieve service descriptor, no response: (RemoteService) Descriptor: /xml/ZoneGroupTopology1.xml
20:40:52.128 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - ‘sonos:PLAY1:RINCON_5CAAFD41063001400’ changed from OFFLINE (COMMUNICATION_ERROR): The Sonos player RINCON_5CAAFD41063001400 is not available in local network. to ONLINE
20:40:52.219 [WARN ] [org.jupnp.transport.spi.StreamClient ] - HTTP request failed: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.XX.XX:1400/MediaRenderer/RenderingControl/Event (HttpConnectionOverHTTP@c1c621(l:/192.168.XX.XX:60837 ↔ r:/192.168.XX.XX:1400,closed=false)[HttpChannelOverHTTP@5d3d74(exchange=HttpExchange@8d5a84 req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@10ebfd0(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@1aa8ede{s=START}],recv=HttpReceiverOverHTTP@fa042(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of 0}]]])
20:40:52.229 [WARN ] [org.jupnp.transport.spi.StreamClient ] - HTTP request failed: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.XX.XX:1400/DeviceProperties/Event (HttpConnectionOverHTTP@b97c16(l:/192.168.XX.XX:60840 ↔ r:/192.168.XX.XX:1400,closed=false)[HttpChannelOverHTTP@adb0b(exchange=HttpExchange@10bea3a req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@19f581e(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@7c8b7{s=START}],recv=HttpReceiverOverHTTP@89847f(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of 0}]]])

I changed org.ops4j.pax.logging.cfg back to default but no change. Any idea?

10

Your log shows no WeMo related issues, so you better start a new conversation instead of hijacking this one.

11

Sorry to re-awaken this old thread, but if people search on “wemo invalid subscriptionid”, it still takes them here.
To get rid of those messages, define all the items corresponding to the wemo insight, even if you are not using them.

So above, for example,

[ERROR] [g.jupnp.protocol.sync.ReceivingEvent] - Invalid subscription ID, no active subscription: (IncomingEventRequestMessage) NOTIFY /upnpcallback/dev/Insight-1_0-xxxxxxxxxxxx1/svc/Belkin/insight1/event/cb SEQUENCE: 148

Just include all the items for the insight binding:

Number InsightPower  { channel="wemo:insight:Insight-1_0-xxxxxxxxxxxx1:currentPower" }
Number InsightLastOn { channel="wemo:insight:Insight-1_0-xxxxxxxxxxxx1:lastOnFor" }
Number InsightToday  { channel="wemo:insight:Insight-1_0-xxxxxxxxxxxx1:onToday" }
Number InsightTotal  { channel="wemo:insight:Insight-1_0-xxxxxxxxxxxx1:onTotal" }

Seems to be needed just for the Insight, which sends periodically.