[Solved] Org.jupnp errors

Dim · January 29, 2017, 10:43am

I am not sure if this is a bug, so I haven’t opened an issue yet… Just checking here with the community to get some ideas…

Running openHAB 2 Snapshot Build #767 on Debian Jessie.

When I modify the default OPENHAB_HTTP_PORT in /etc/default/openhab2 to:

EXTRA_JAVA_OPTS=""
OPENHAB_HTTP_PORT=8081
OPENHAB_HTTPS_PORT=8444

and change the default log level for org.jupnp from ERROR to WARN, I get the following in openhab.log:

2017-01-29 12:32:19.081 [WARN ] [p.protocol.RetrieveRemoteDescriptors] - Device descriptor retrieval failed, no response: http://172.16.13.100:8080/upnp
2017-01-29 12:33:19.085 [WARN ] [p.protocol.RetrieveRemoteDescriptors] - Device descriptor retrieval failed: http://172.16.13.100:8080/upnp, 404 Not Found
2017-01-29 12:34:19.087 [WARN ] [org.jupnp.transport.spi.StreamClient] - HTTP request failed: (StreamRequestMessage) GET http://172.16.13.100:8080/upnp
org.apache.http.NoHttpResponseException: The target server failed to respond
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)[37:org.apache.httpcomponents.httpcore:4.2.3]
	at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)[37:org.apache.httpcomponents.httpcore:4.2.3]
	at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)[37:org.apache.httpcomponents.httpcore:4.2.3]
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)[37:org.apache.httpcomponents.httpcore:4.2.3]
	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:1066)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:1044)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:1035)[36: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_121]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_121]
	at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]

Is it because within https://github.com/jupnp/jupnp/blob/master/bundles/org.jupnp/jUPnP.launch the jetty port is hardcoded in the code?

<stringAttribute key="org.eclipse.jdt.launching.VM_ARGUMENTS" value="-Declipse.ignoreApp=true -Dosgi.noShutdown=true -Djetty.home.bundle=org.eclipse.jetty.osgi.boot -Djetty.port=8080 -Djetty.port.ssl=8443"/>

Ps: I run a Unifi Controller on 8080 & 8443 on the local machine (IP: 172.16.13.100)
Ps2: URL http://172.16.13.100:8081/upnp also gives me 404
Ps3: Everything is working fine (including thing discovery)… this is just a warning that I get which doesn’t seem to affect the functionality of my openHAB 2 system.

Dim · January 30, 2017, 4:13pm

I installed OH2 Snapshot #771 on a rPi3 (IP: 172.16.13.101) and I get the same errors in openhab.log (it receives UDP broadcasts from the other host running on IP 172.16.13.100 it seems)

2017-01-30 18:10:21.059 [WARN ] [org.jupnp.transport.spi.StreamClient] - HTTP request failed: (StreamRequestMessage) GET http://172.16.13.100:8080/upnp
org.apache.http.NoHttpResponseException: The target server failed to respond
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)[37:org.apache.httpcomponents.httpcore:4.2.3]
	at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)[37:org.apache.httpcomponents.httpcore:4.2.3]
	at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)[37:org.apache.httpcomponents.httpcore:4.2.3]
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)[37:org.apache.httpcomponents.httpcore:4.2.3]
	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:1066)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:1044)[36:org.apache.httpcomponents.httpclient:4.2.3]
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:1035)[36: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_65]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_65]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_65]
	at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]
2017-01-30 18:10:21.077 [WARN ] [p.protocol.RetrieveRemoteDescriptors] - Device descriptor retrieval failed, no response: http://172.16.13.100:8080/upnp

I don’t even know what org.jupnp does, but something seems to go wrong with it when the HTTP port is changed in a OH2 installation.

Dim · January 30, 2017, 4:40pm

Ok… I did some more digging into this…

It is NOT a problem of OH2 after all… (my bad)

It looks like a problem of the Unifi Controller software that does not respond properly to the HTTP queries.

From what I understand: The Plug-n-Play service of OH2 listens to UDP broadcasts from multiple devices on the local network.

In most of the cases, it identifies the remote devices but in the case of Unifi Controller software version 5.4.9, it pops up a problem:

2017-01-30 18:16:21.046 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 172.16.13.100:1900 on local interface: eth0 and address: 172.16.13.101
2017-01-30 18:16:21.047 [TRACE] [upnp.transport.spi.DatagramProcessor] - ====== DATAGRAM BEGIN ======
2017-01-30 18:16:21.048 [TRACE] [upnp.transport.spi.DatagramProcessor] - NOTIFY * HTTP/1.1^M
Host: 239.255.255.250:1900^M
Cache-Control: max-age = 60^M
Location: http://172.16.13.100:8080/upnp^M
NTS: ssdp:alive^M
SERVER: UPnP/1.0 UniFi/5.4.9^M
NT: urn:schemas-upnp-org:device:upnp:1^M
USN: uuid:3C86D905-39E4-4FDC-963C-04E19F2791BB::urn:schemas-upnp-org:device:upnp:1^M
^M
^@^@^@^@^@^@
2017-01-30 18:16:21.049 [TRACE] [upnp.transport.spi.DatagramProcessor] - -====== DATAGRAM END ======

[...]

2017-01-30 18:10:21.059 [WARN ] [org.jupnp.transport.spi.StreamClient] - HTTP request failed: (StreamRequestMessage) GET http://172.16.13.100:8080/upnp

Case closed

Dim · January 30, 2017, 4:57pm

Just a note for others who maybe running Unifi Controller (version 5.4.9):

It is a bug in that software. The Unify controller reports that ‘/upnp’ url as a response to SSDP discovery requests, but when it is retrieved it really does return an Apache Tomcat 404 error page.

To disable it: go to the Unifi Controller webpage, in the bottom left there is a pair of gears (settings), then pick ‘Controller’, which has a ‘Controller Settings’ section where you find a ‘Network Discovery’ checkbox. Unchecking that checkbox will make the controller not respond to SSDP discovery requests.