OpenHAB2 not receiving notification from WeMo correctly

Add-ons Bindings
, ,
1

Hi everybody!

I don’t have a WeMo device but i have make a Java program that emulate WeMo switch (just for testing, and, late, i want to make a faux WeMo device, based on fauxmo from makermusings and witnessmenow/esp8266-alexa-wemo-emulator, on github).

Everything works great, but I found one problem in subscribtion on WeMo switch event. I see a strange behavior (in papper UI) when my faux switch send a NOTIFY: openHAB make state of switch always ON, regardless what i send in BinariState tag. I always send a 0, but state of switch always changing (or stay) to ON. If i turned him OFF (form openHAB) and send a NOTIFY which sayed that switch is OFF, strangtly, openHAB change state of switch to ON! ???

This is what i send from Java:

NOTIFY /upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb HTTP/1.1
HOST: 192.168.1.105:8080
CONTENT-TYPE: text/xml; charset="utf-8"
CONTENT-LENGTH: 140
NT: upnp:event
NTS: upnp:propchange
SID: uuid:904bfa3c-1de2-11v2-8728-fd8eebaf4929
SEQ: 1

<e:propertyset xmlns:e="urn:schemas-upnp-org:event-1-0">
 <e:property>
    <BinaryState>0</BinaryState>
  </e:property>
</e:propertyset>

and openHAB response:

HTTP/1.1 200 OK
Date: Wed, 30 Aug 2017 00:37:25 GMT
Content-Type: text/xml
Content-Length: 0
Server: Jetty(9.2.19.v20160908)

What I missed?
Dejan

2

There is log file received when WeMo send NOTIFY:

2017-08-31 19:01:07.665 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@125ddd8
2017-08-31 19:01:07.667 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 0/2 selected
2017-08-31 19:01:07.669 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@125ddd8
2017-08-31 19:01:07.671 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - onOpen SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,0/30000,null}{io=0,kio=0,kro=0}
2017-08-31 19:01:07.674 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms
2017-08-31 19:01:07.678 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - new HttpChannelOverHttp@7a7966{r=0,c=false,a=IDLE,uri=} -> SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,7/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@ad04e5{s=IDLE i=true a=null}
2017-08-31 19:01:07.682 [DEBUG] [.eclipse.jetty.server.HttpConnection] - New HTTP Connection HttpConnection@a97a67[IDLE,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,11/30000,null}{io=0,kio=0,kro=0}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=0,c=false,a=IDLE,uri=}]
2017-08-31 19:01:07.686 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - onOpen HttpConnection@a97a67[IDLE,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,15/30000,HttpConnection}{io=0,kio=0,kro=0}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=0,c=false,a=IDLE,uri=}]
2017-08-31 19:01:07.690 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested HttpConnection@a97a67[IDLE,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,19/30000,HttpConnection}{io=0,kio=0,kro=0}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=0,c=false,a=IDLE,uri=}]
2017-08-31 19:01:07.694 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - IDLE-->FILL_INTERESTED HttpConnection@a97a67[FILL_INTERESTED,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,23/30000,HttpConnection}{io=0,kio=0,kro=0}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=0,c=false,a=IDLE,uri=}]
2017-08-31 19:01:07.697 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 0 -> 1 for SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}
2017-08-31 19:01:07.700 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@16fba22
2017-08-31 19:01:07.702 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Created SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,R,-,6/30000,HttpConnection}{io=1,kio=0,kro=0}
2017-08-31 19:01:07.705 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@16fba22
2017-08-31 19:01:07.708 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 0 -> 1 on SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,R,-,11/30000,HttpConnection}{io=1,kio=1,kro=0}
2017-08-31 19:01:07.710 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
2017-08-31 19:01:07.712 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 1/3 selected
2017-08-31 19:01:07.715 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 1 -> 0 on SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,R,-,19/30000,HttpConnection}{io=1,kio=0,kro=1}
2017-08-31 19:01:07.718 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 1 -> 0 for SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,R,-,22/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 19:01:07.721 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@16fba22
2017-08-31 19:01:07.724 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILL_INTERESTED-->FILLING HttpConnection@a97a67[FILLING,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,27/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=0,c=false,a=IDLE,uri=}]
2017-08-31 19:01:07.727 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@16fba22
2017-08-31 19:01:07.729 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@a97a67[FILLING,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,31/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=0,c=false,a=IDLE,uri=}] onFillable HttpChannelState@ad04e5{s=IDLE i=true a=null}
2017-08-31 19:01:07.729 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
2017-08-31 19:01:07.732 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 419 SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,35/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 19:01:07.733 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@1560d29[p=0,l=419,c=8192,r=419]={<<<NOTIFY /upnpcallb...opertyset>\n\n\r\r\n>>>\nche-Control: max...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-08-31 19:01:07.734 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> METHOD
2017-08-31 19:01:07.735 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - METHOD --> SPACE1
2017-08-31 19:01:07.737 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE1 --> URI
2017-08-31 19:01:07.738 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - URI --> SPACE2
2017-08-31 19:01:07.739 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE2 --> REQUEST_VERSION
2017-08-31 19:01:07.740 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - REQUEST_VERSION --> HEADER
2017-08-31 19:01:07.742 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_VALUE
2017-08-31 19:01:07.743 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 19:01:07.744 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 19:01:07.745 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
2017-08-31 19:01:07.746 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 19:01:07.748 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_VALUE
2017-08-31 19:01:07.749 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 19:01:07.751 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 19:01:07.752 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
2017-08-31 19:01:07.754 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
2017-08-31 19:01:07.755 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 19:01:07.756 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 19:01:07.758 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
2017-08-31 19:01:07.759 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
2017-08-31 19:01:07.759 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 19:01:07.760 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 19:01:07.761 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
2017-08-31 19:01:07.762 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
2017-08-31 19:01:07.763 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 19:01:07.764 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 19:01:07.765 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
2017-08-31 19:01:07.766 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
2017-08-31 19:01:07.766 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 19:01:07.767 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 19:01:07.768 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> CONTENT
2017-08-31 19:01:07.770 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@7a7966{r=1,c=false,a=IDLE,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb} handle enter
2017-08-31 19:01:07.771 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@ad04e5{s=IDLE i=true a=null} handling IDLE
2017-08-31 19:01:07.772 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@7a7966{r=1,c=false,a=DISPATCHED,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb} action REQUEST_DISPATCH
2017-08-31 19:01:07.773 [DEBUG] [org.eclipse.jetty.server.Server     ] - REQUEST NOTIFY /upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb on HttpChannelOverHttp@7a7966{r=1,c=false,a=DISPATCHED,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb}
2017-08-31 19:01:07.774 [DEBUG] [ax.web.service.spi.model.ServerModel] - Matching [/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb]...
2017-08-31 19:01:07.776 [DEBUG] [ax.web.service.spi.model.ServerModel] - Path [/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb] matched to {pattern=/upnpcallback/.*,model=ServletModel{id=org.ops4j.pax.web.service.spi.model.ServletModel-15,name=org.ops4j.pax.web.service.spi.model.ServletModel-15,urlPatterns=[/upnpcallback/*],alias=/upnpcallback,servlet=org.jupnp.transport.impl.async.AsyncServlet@e68acf,initParams={},context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-14,name=,httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@7a93aa,contextParams={},virtualHosts={},connectors={}}}}
2017-08-31 19:01:07.777 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@7a93aa}
2017-08-31 19:01:07.778 [DEBUG] [.jetty.server.handler.ContextHandler] - context=||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@7a93aa}
2017-08-31 19:01:07.779 [DEBUG] [org.eclipse.jetty.server.session    ] - sessionManager=org.ops4j.pax.web.service.jetty.internal.LateInvalidatingHashSessionManager@a049b0
2017-08-31 19:01:07.780 [DEBUG] [org.eclipse.jetty.server.session    ] - session=null
2017-08-31 19:01:07.781 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - servlet |/upnpcallback|/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb -> org.ops4j.pax.web.service.spi.model.ServletModel-15@b9f03e5c==org.jupnp.transport.impl.async.AsyncServlet,-1,true
2017-08-31 19:01:07.782 [DEBUG] [ce.jetty.internal.HttpServiceContext] - Handling request for [/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb] using http context [org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@7a93aa]
2017-08-31 19:01:07.783 [DEBUG] [y.internal.HttpServiceServletHandler] - handling request org.ops4j.pax.web.service.jetty.internal.HttpServiceRequestWrapper@147fefc, org.ops4j.pax.web.service.jetty.internal.HttpServiceResponseWrapper@18013e4
2017-08-31 19:01:07.784 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - chain=null
2017-08-31 19:01:07.786 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ o.e.j.s.h.ContextHandler@eadc1a{/static,null,AVAILABLE}
2017-08-31 19:01:07.791 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=CONTENT HeapByteBuffer@1560d29[p=277,l=419,c=8192,r=142]={NOTIFY /upnpcallb...929\r\nSEQ: 0\r\n\r\n<<<<e:propertyset xm...opertyset>\n\n\r\r\n>>>\nche-Control: max...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-08-31 19:01:07.792 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default]}
2017-08-31 19:01:07.792 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]}
2017-08-31 19:01:07.793 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@7a7966{r=1,c=false,a=DISPATCHED,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb} content java.nio.HeapByteBufferR[pos=277 lim=417 cap=8192]
2017-08-31 19:01:07.793 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]}
2017-08-31 19:01:07.794 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=CONTENT HeapByteBuffer@1560d29[p=417,l=419,c=8192,r=2]={NOTIFY /upnpcallb...propertyset>\n\n\r<<<\r\n>>>\nche-Control: max...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-08-31 19:01:07.794 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.classic_0.9.0.b5 [197], contextID=default]}
2017-08-31 19:01:07.795 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - CONTENT --> END
2017-08-31 19:01:07.796 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [198], contextID=default]}
2017-08-31 19:01:07.797 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@7a7966{r=1,c=false,a=DISPATCHED,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb} messageComplete
2017-08-31 19:01:07.798 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@1b0875a EOF
2017-08-31 19:01:07.798 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.1.0 [203], contextID=default]}
2017-08-31 19:01:07.800 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,67/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 19:01:07.801 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default]}
2017-08-31 19:01:07.803 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@a97a67[FILLING,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,69/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,140 of 140},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=1,c=false,a=DISPATCHED,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb}] filled 0
2017-08-31 19:01:07.803 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default]}
2017-08-31 19:01:07.804 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@1b0875a eof EOF
2017-08-31 19:01:07.805 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@1b0875a eof EOF
2017-08-31 19:01:07.805 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default]}
2017-08-31 19:01:07.808 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [196], contextID=default]}
2017-08-31 19:01:07.809 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.io.rest.docs_2.1.0 [199], contextID=default]}
2017-08-31 19:01:07.811 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habmin_2.1.0 [202], contextID=default]}
2017-08-31 19:01:07.813 [DEBUG] [org.eclipse.jetty.server.Server     ] - RESPONSE /upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb  200 handled=true
2017-08-31 19:01:07.815 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@ad04e5{s=DISPATCHED i=true a=STARTED} unhandle DISPATCHED
2017-08-31 19:01:07.817 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@7a7966{r=1,c=false,a=ASYNC_WAIT,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb} handle exit, result WAIT
2017-08-31 19:01:07.818 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@7a7966{r=1,c=false,a=ASYNC_WOKEN,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb} handle enter
2017-08-31 19:01:07.822 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1092adf[PROCESSING][i=null,cb=Blocker@170a3b3{null}] generate: FLUSH (null,[p=0,l=188,c=32768,r=188],false)@COMMITTED
2017-08-31 19:01:07.823 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'ON' for item 'Java' to handler for channel 'wemo:socket:Socket-1_0-221517K0101737:state', because no thing with the UID 'wemo:socket:Socket-1_0-221517K0101737' could be found.
2017-08-31 19:01:07.824 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@eba10c{IDLE} [HeapByteBuffer@1583c4e[p=0,l=6,c=1024,r=6]={<<<\r\nBC\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@12bd489[p=0,l=188,c=32768,r=188]={<<<event: message\nda...usInfoEvent"}\n\n>>>"}\n\ntusDetail\\":\\...centrale/readme}]
2017-08-31 19:01:07.825 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@ad04e5{s=ASYNC_WOKEN i=false a=COMPLETE} handling ASYNC_WOKEN
2017-08-31 19:01:07.824 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'ON' for item 'Java' to handler for channel 'wemo:socket:Socket-1_0-221517K0101727:state', because no thing with the UID 'wemo:socket:Socket-1_0-221517K0101727' could be found.
2017-08-31 19:01:07.826 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@eba10c{WRITING}:IDLE-->WRITING
2017-08-31 19:01:07.827 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'ON' for item 'Java' to handler for channel 'wemo:socket:Socket-1_0-221517K0101717:state', because no thing with the UID 'wemo:socket:Socket-1_0-221517K0101717' could be found.
2017-08-31 19:01:07.829 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 194 SelectChannelEndPoint@de29bf{/192.168.1.11:40286<->8080,Open,in,out,-,W,7233/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 19:01:07.830 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@eba10c{IDLE}:WRITING-->IDLE
2017-08-31 19:01:07.831 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@148ec2a[PROCESSING][i=ResponseInfo{HTTP/1.1 200 null,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@4a7a67] generate: NEED_HEADER (null,[p=0,l=0,c=0,r=0],true)@START
2017-08-31 19:01:07.832 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1092adf[PROCESSING][i=null,cb=Blocker@170a3b3{null}] generate: DONE (null,[p=188,l=188,c=32768,r=0],false)@COMMITTED
2017-08-31 19:01:07.829 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'ON' for item 'Java' to handler for channel 'wemo:socket:Socket-1_0-221517K0101777:state', because no thing with the UID 'wemo:socket:Socket-1_0-221517K0101777' could be found.
2017-08-31 19:01:07.834 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING-->IDLE HttpConnection@a97a67[IDLE,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,88/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,140 of 140},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=1,c=false,a=COMPLETED,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb}]
2017-08-31 19:01:07.833 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@148ec2a[PROCESSING][i=ResponseInfo{HTTP/1.1 200 null,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@4a7a67] generate: FLUSH ([p=0,l=132,c=8192,r=132],[p=0,l=0,c=0,r=0],true)@COMPLETING
2017-08-31 19:01:07.834 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'ON' for item 'Java' to handler for channel 'wemo:socket:Socket-1_0-221517K0101747:state', because no thing with the UID 'wemo:socket:Socket-1_0-221517K0101747' could be found.
2017-08-31 19:01:07.836 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1092adf[PROCESSING][i=null,cb=Blocker@170a3b3{null}] generate: FLUSH (null,[p=0,l=135,c=32768,r=135],false)@COMMITTED
2017-08-31 19:01:07.838 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@eba10c{IDLE} [HeapByteBuffer@1583c4e[p=0,l=6,c=1024,r=6]={<<<\r\n87\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@12bd489[p=0,l=135,c=32768,r=135]={<<<event: message\nda...mStateEvent"}\n\n>>>sDetail\\":\\"NONE\\...centrale/readme}]
2017-08-31 19:01:07.838 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@10fb7e3{IDLE} [HeapByteBuffer@35ca89[p=0,l=132,c=8192,r=132]={<<<HTTP/1.1 200 OK\r\n....v20160908)\r\n\r\n>>> text/xml; charse...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]
2017-08-31 19:01:07.839 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@eba10c{WRITING}:IDLE-->WRITING
2017-08-31 19:01:07.840 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@10fb7e3{WRITING}:IDLE-->WRITING
2017-08-31 19:01:07.842 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 141 SelectChannelEndPoint@de29bf{/192.168.1.11:40286<->8080,Open,in,out,-,W,11/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 19:01:07.843 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@eba10c{IDLE}:WRITING-->IDLE
2017-08-31 19:01:07.844 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1092adf[PROCESSING][i=null,cb=Blocker@170a3b3{null}] generate: DONE (null,[p=135,l=135,c=32768,r=0],false)@COMMITTED
2017-08-31 19:01:07.843 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 132 SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,W,110/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 19:01:07.847 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@10fb7e3{IDLE}:WRITING-->IDLE
2017-08-31 19:01:07.850 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1092adf[PROCESSING][i=null,cb=Blocker@170a3b3{null}] generate: FLUSH (null,[p=0,l=192,c=32768,r=192],false)@COMMITTED
2017-08-31 19:01:07.851 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@eba10c{IDLE} [HeapByteBuffer@1583c4e[p=0,l=6,c=1024,r=6]={<<<\r\nC0\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@12bd489[p=0,l=192,c=32768,r=192]={<<<event: message\nda...hangedEvent"}\n\n>>>tusDetail\\":\\"COM...centrale/readme}]
2017-08-31 19:01:07.851 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@148ec2a[PROCESSING][i=ResponseInfo{HTTP/1.1 200 null,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@4a7a67] generate: DONE ([p=132,l=132,c=8192,r=0],[p=0,l=0,c=0,r=0],true)@END
2017-08-31 19:01:07.852 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@eba10c{WRITING}:IDLE-->WRITING
2017-08-31 19:01:07.853 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - reset HttpParser{s=END,140 of 140}
2017-08-31 19:01:07.854 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - END --> START
2017-08-31 19:01:07.854 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 198 SelectChannelEndPoint@de29bf{/192.168.1.11:40286<->8080,Open,in,out,-,W,12/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 19:01:07.856 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@eba10c{IDLE}:WRITING-->IDLE
2017-08-31 19:01:07.857 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested HttpConnection@a97a67[IDLE,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,9/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=1,c=false,a=IDLE,uri=}]
2017-08-31 19:01:07.858 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1092adf[PROCESSING][i=null,cb=Blocker@170a3b3{null}] generate: DONE (null,[p=192,l=192,c=32768,r=0],false)@COMMITTED
2017-08-31 19:01:07.859 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - IDLE-->FILL_INTERESTED HttpConnection@a97a67[FILL_INTERESTED,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,12/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=1,c=false,a=IDLE,uri=}]
2017-08-31 19:01:07.860 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 0 -> 1 for SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=1}
2017-08-31 19:01:07.861 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@16fba22
2017-08-31 19:01:07.862 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 0/3 selected
2017-08-31 19:01:07.863 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@7a7966{r=1,c=false,a=IDLE,uri=} handle exit, result COMPLETE
2017-08-31 19:01:07.864 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@16fba22
2017-08-31 19:01:07.866 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 0 -> 1 on SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,R,-,5/30000,HttpConnection}{io=1,kio=1,kro=1}
2017-08-31 19:01:07.867 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
2017-08-31 19:01:07.869 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 1/3 selected
2017-08-31 19:01:07.871 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 1 -> 0 on SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,R,-,10/30000,HttpConnection}{io=1,kio=0,kro=1}
2017-08-31 19:01:07.873 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 1 -> 0 for SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,R,-,12/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 19:01:07.875 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@16fba22
2017-08-31 19:01:07.877 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILL_INTERESTED-->FILLING HttpConnection@a97a67[FILLING,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,16/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=1,c=false,a=IDLE,uri=}]
2017-08-31 19:01:07.879 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@16fba22
2017-08-31 19:01:07.880 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@a97a67[FILLING,SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,19/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@7a7966{r=1,c=false,a=IDLE,uri=}] onFillable HttpChannelState@ad04e5{s=IDLE i=true a=null}
2017-08-31 19:01:07.881 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
2017-08-31 19:01:07.882 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled -1 SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,21/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 19:01:07.883 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - ishut SelectChannelEndPoint@39eece{/192.168.1.11:40561<->8080,Open,in,out,-,-,23/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 19:01:07.884 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - atEOF HttpParser{s=START,0 of -1}
2017-08-31 19:01:07.885 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@1d090e0[p=0,l=0,c=8192,r=0]={<<<>>>GET /rest/events ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-08-31 19:01:07.886 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> CLOSED
3

???
What are you trying to achieve ?

As I understood, you emulate a WeMo device outside openHab.
How do you want to receive the notification ?
I don’t see anything from the WeMo binding in the logs you provided.

4

I try to report state change, from WeMo to openHAB. OpenHAB do SUBSCRIBE to my WeMo, and, after subscription received, WeMo switch sends notifications to openHAB, everytime when somebody change state of the switch. Then openHAB immediately knows that state is changed.
In the log, you can find line:

2017-08-31 19:01:07.734 [DEBUG] [org.eclipse.jetty.http.HttpParser ] - START --> METHOD

And after that line, folows listing, for which i suppose that represent reading lines from my Java program. After that, a I can not interpret what lines means.
I only see that openHAB reacts on NOTIFY, but not as expected. Regardless what i send as BinaryState (0 or 1), openHAB always change state of bindings to ON. I cant figure out why :frowning:

5

So your wrote “something” to receive notifications from your wemo emulation.
Why?
Ther is an existing WeMo binding which already supports GENA events.

6

First, thank you so much four your interests to help, and your patience for me!
No, no. I just wrote “something” to emulate real WeMo switch. I use existing WeMo binding, but i have problem with this GENA events. I don’t know how exactly lets say, comunicate with devices by GENA rules. I mean, that switch simply send notifications to openHAB (i found some description about data needed to be send from switch) but… that does not work for me, and i can’t figure out why, and i don’t have a real WeMo switch to do some kind of reverse engineering, and capture what exactly he send to subscriber. Also, I do not know how openHAB WeMo bindings work, and what he expect from device. You can see what exactli i send from my “faux WeMo”, but that does not work well :frowning:

OH2 wemo
OH2 wemo.jpg1001×454 171 KB

7

As I wrote the WeMo binding, I am always interested in issues the users face :wink:

The GENA event system is implemented in JUPnP and is following the UPnP standards.
Once a device sends a notify message, the changed property will be passed from JUPnP to the according binding.
This is working for WeMo, SONOS and other UPnP capable devices.

In your logs, I don’t see anything related to jupnp.transport or WeMo binding.
Are you able to control your virtual WeMo device from within openHAB?

8

I glad to hear that! :slight_smile:

Absolutely! Everything works fine! My program detects every click on button, and normally sends response to GetBinaryState (i mean, about every 2 minutes) from openHAB. And, openHAB perfectli set state of the button to what I sent from Java program (emulated Wemo switch)… Except NOTIFY reporting. Please, see my first post. This is what i send to openHAB, and below is OK status, what openHAB respond to NOTIFY. But… :frowning:
I try to catch new log and attach them in a few minutes…

9

Are you sure you send to the correct port?
When openhab subscribes to your virtual device, it is telling which port is used for receiving notify messages.

10

Yes, becouse openHAB always react to my sending. But, this reactions is always same: state always change to ON, regardles what i put in BinaryState tag: 0 or 1

11

Here is another log capture. Becouse of site limitations, i try to split it in 2 posts:

2017-08-31 21:36:16.918 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2017-08-31 21:36:21.015 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@8b6527
2017-08-31 21:36:21.018 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 0/2 selected
2017-08-31 21:36:21.020 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@8b6527
2017-08-31 21:36:21.022 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - onOpen SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,1/30000,null}{io=0,kio=0,kro=0}
2017-08-31 21:36:21.025 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms
2017-08-31 21:36:21.029 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - new HttpChannelOverHttp@66551{r=0,c=false,a=IDLE,uri=} -> SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,7/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@6410ff{s=IDLE i=true a=null}
2017-08-31 21:36:21.032 [DEBUG] [.eclipse.jetty.server.HttpConnection] - New HTTP Connection HttpConnection@1f1725f[IDLE,SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,10/30000,null}{io=0,kio=0,kro=0}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@66551{r=0,c=false,a=IDLE,uri=}]
2017-08-31 21:36:21.036 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - onOpen HttpConnection@1f1725f[IDLE,SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,14/30000,HttpConnection}{io=0,kio=0,kro=0}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@66551{r=0,c=false,a=IDLE,uri=}]
2017-08-31 21:36:21.040 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested HttpConnection@1f1725f[IDLE,SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,18/30000,HttpConnection}{io=0,kio=0,kro=0}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@66551{r=0,c=false,a=IDLE,uri=}]
2017-08-31 21:36:21.044 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - IDLE-->FILL_INTERESTED HttpConnection@1f1725f[FILL_INTERESTED,SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,22/30000,HttpConnection}{io=0,kio=0,kro=0}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@66551{r=0,c=false,a=IDLE,uri=}]
2017-08-31 21:36:21.048 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 0 -> 1 for SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}
2017-08-31 21:36:21.051 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d63014
2017-08-31 21:36:21.054 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Created SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,R,-,6/30000,HttpConnection}{io=1,kio=0,kro=0}
2017-08-31 21:36:21.056 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d63014
2017-08-31 21:36:21.060 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 0 -> 1 on SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,R,-,12/30000,HttpConnection}{io=1,kio=1,kro=0}
2017-08-31 21:36:21.062 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
2017-08-31 21:36:21.065 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 1/3 selected
2017-08-31 21:36:21.068 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 1 -> 0 on SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,R,-,21/30000,HttpConnection}{io=1,kio=0,kro=1}
2017-08-31 21:36:21.072 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 1 -> 0 for SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,R,-,24/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.075 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d63014
2017-08-31 21:36:21.078 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILL_INTERESTED-->FILLING HttpConnection@1f1725f[FILLING,SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,30/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@66551{r=0,c=false,a=IDLE,uri=}]
2017-08-31 21:36:21.081 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d63014
2017-08-31 21:36:21.083 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@1f1725f[FILLING,SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,35/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@66551{r=0,c=false,a=IDLE,uri=}] onFillable HttpChannelState@6410ff{s=IDLE i=true a=null}
2017-08-31 21:36:21.084 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
2017-08-31 21:36:21.087 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 419 SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,39/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.089 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@69c28b[p=0,l=419,c=8192,r=419]={<<<NOTIFY /upnpcallb...opertyset>\n\n\r\r\n>>>\r\n38000\r\n\r\nInfo":...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-08-31 21:36:21.090 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> METHOD
2017-08-31 21:36:21.092 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - METHOD --> SPACE1
2017-08-31 21:36:21.093 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE1 --> URI
2017-08-31 21:36:21.095 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - URI --> SPACE2
2017-08-31 21:36:21.096 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE2 --> REQUEST_VERSION
2017-08-31 21:36:21.098 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - REQUEST_VERSION --> HEADER
2017-08-31 21:36:21.099 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_VALUE
2017-08-31 21:36:21.101 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 21:36:21.102 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 21:36:21.104 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
2017-08-31 21:36:21.105 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 21:36:21.107 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_VALUE
2017-08-31 21:36:21.109 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 21:36:21.110 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 21:36:21.112 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
2017-08-31 21:36:21.113 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
2017-08-31 21:36:21.114 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 21:36:21.116 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 21:36:21.117 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
2017-08-31 21:36:21.119 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
2017-08-31 21:36:21.120 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 21:36:21.121 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 21:36:21.122 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
2017-08-31 21:36:21.123 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
2017-08-31 21:36:21.124 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 21:36:21.126 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 21:36:21.127 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
2017-08-31 21:36:21.128 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
2017-08-31 21:36:21.129 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
2017-08-31 21:36:21.130 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
2017-08-31 21:36:21.131 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> CONTENT
12

Continue of log:

2017-08-31 21:36:21.133 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@66551{r=1,c=false,a=IDLE,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb} handle enter
2017-08-31 21:36:21.134 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@6410ff{s=IDLE i=true a=null} handling IDLE
2017-08-31 21:36:21.136 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@66551{r=1,c=false,a=DISPATCHED,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb} action REQUEST_DISPATCH
2017-08-31 21:36:21.138 [DEBUG] [org.eclipse.jetty.server.Server     ] - REQUEST NOTIFY /upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb on HttpChannelOverHttp@66551{r=1,c=false,a=DISPATCHED,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb}
2017-08-31 21:36:21.139 [DEBUG] [ax.web.service.spi.model.ServerModel] - Matching [/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb]...
2017-08-31 21:36:21.141 [DEBUG] [ax.web.service.spi.model.ServerModel] - Path [/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb] matched to {pattern=/upnpcallback/.*,model=ServletModel{id=org.ops4j.pax.web.service.spi.model.ServletModel-15,name=org.ops4j.pax.web.service.spi.model.ServletModel-15,urlPatterns=[/upnpcallback/*],alias=/upnpcallback,servlet=org.jupnp.transport.impl.async.AsyncServlet@e68acf,initParams={},context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-14,name=,httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@7a93aa,contextParams={},virtualHosts={},connectors={}}}}
2017-08-31 21:36:21.142 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@7a93aa}
2017-08-31 21:36:21.143 [DEBUG] [.jetty.server.handler.ContextHandler] - context=||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@7a93aa}
2017-08-31 21:36:21.145 [DEBUG] [org.eclipse.jetty.server.session    ] - sessionManager=org.ops4j.pax.web.service.jetty.internal.LateInvalidatingHashSessionManager@a049b0
2017-08-31 21:36:21.146 [DEBUG] [org.eclipse.jetty.server.session    ] - session=null
2017-08-31 21:36:21.147 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - servlet |/upnpcallback|/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb -> org.ops4j.pax.web.service.spi.model.ServletModel-15@b9f03e5c==org.jupnp.transport.impl.async.AsyncServlet,-1,true
2017-08-31 21:36:21.149 [DEBUG] [ce.jetty.internal.HttpServiceContext] - Handling request for [/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb] using http context [org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@7a93aa]
2017-08-31 21:36:21.150 [DEBUG] [y.internal.HttpServiceServletHandler] - handling request org.ops4j.pax.web.service.jetty.internal.HttpServiceRequestWrapper@20cf6d, org.ops4j.pax.web.service.jetty.internal.HttpServiceResponseWrapper@3172ca
2017-08-31 21:36:21.151 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - chain=null
2017-08-31 21:36:21.154 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ o.e.j.s.h.ContextHandler@eadc1a{/static,null,AVAILABLE}
2017-08-31 21:36:21.159 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=CONTENT HeapByteBuffer@69c28b[p=277,l=419,c=8192,r=142]={NOTIFY /upnpcallb...929\r\nSEQ: 6\r\n\r\n<<<<e:propertyset xm...opertyset>\n\n\r\r\n>>>\r\n38000\r\n\r\nInfo":...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-08-31 21:36:21.160 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@66551{r=1,c=false,a=DISPATCHED,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb} content java.nio.HeapByteBufferR[pos=277 lim=417 cap=8192]
2017-08-31 21:36:21.161 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=CONTENT HeapByteBuffer@69c28b[p=417,l=419,c=8192,r=2]={NOTIFY /upnpcallb...propertyset>\n\n\r<<<\r\n>>>\r\n38000\r\n\r\nInfo":...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-08-31 21:36:21.162 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - CONTENT --> END
2017-08-31 21:36:21.160 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default]}
2017-08-31 21:36:21.163 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@66551{r=1,c=false,a=DISPATCHED,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb} messageComplete
2017-08-31 21:36:21.164 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@17b5476 EOF
2017-08-31 21:36:21.164 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]}
2017-08-31 21:36:21.165 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,77/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.166 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]}
2017-08-31 21:36:21.167 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@1f1725f[FILLING,SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,78/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,140 of 140},g=HttpGenerator{s=START},c=HttpChannelOverHttp@66551{r=1,c=false,a=DISPATCHED,uri=/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb}] filled 0
2017-08-31 21:36:21.167 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.classic_0.9.0.b5 [197], contextID=default]}
2017-08-31 21:36:21.168 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@17b5476 eof EOF
2017-08-31 21:36:21.169 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@17b5476 eof EOF
2017-08-31 21:36:21.169 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [198], contextID=default]}
2017-08-31 21:36:21.171 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.1.0 [203], contextID=default]}
2017-08-31 21:36:21.172 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default]}
2017-08-31 21:36:21.174 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default]}
2017-08-31 21:36:21.176 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default]}
2017-08-31 21:36:21.178 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [196], contextID=default]}
2017-08-31 21:36:21.180 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.io.rest.docs_2.1.0 [199], contextID=default]}
2017-08-31 21:36:21.182 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habmin_2.1.0 [202], contextID=default]}
2017-08-31 21:36:21.183 [DEBUG] [org.eclipse.jetty.server.Server     ] - RESPONSE /upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb  200 handled=true
2017-08-31 21:36:21.186 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@6410ff{s=DISPATCHED i=true a=COMPLETE} unhandle DISPATCHED
2017-08-31 21:36:21.188 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@179abcc[PROCESSING][i=ResponseInfo{HTTP/1.1 200 null,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1ed55c9] generate: NEED_HEADER (null,[p=0,l=0,c=0,r=0],true)@START
2017-08-31 21:36:21.190 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@179abcc[PROCESSING][i=ResponseInfo{HTTP/1.1 200 null,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1ed55c9] generate: FLUSH ([p=0,l=132,c=8192,r=132],[p=0,l=0,c=0,r=0],true)@COMPLETING
2017-08-31 21:36:21.190 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@687284[PROCESSING][i=null,cb=Blocker@19c2423{null}] generate: FLUSH (null,[p=0,l=188,c=32768,r=188],false)@COMMITTED
2017-08-31 21:36:21.192 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@162b713{IDLE} [HeapByteBuffer@35ca89[p=0,l=132,c=8192,r=132]={<<<HTTP/1.1 200 OK\r\n....v20160908)\r\n\r\n>>>19.v20160908)\r\n\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]
2017-08-31 21:36:21.194 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@162b713{WRITING}:IDLE-->WRITING
2017-08-31 21:36:21.195 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@1e818f7{IDLE} [HeapByteBuffer@18677ec[p=0,l=6,c=1024,r=6]={<<<\r\nBC\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@b6f3d2[p=0,l=188,c=32768,r=188]={<<<event: message\nda...usInfoEvent"}\n\n>>>"}\n\n}\n\n.47-.76.34...\xFf\xF4%\xEfrr\xE3\x86^\x11L\x8cNP\x9e}]
2017-08-31 21:36:21.197 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1e818f7{WRITING}:IDLE-->WRITING
2017-08-31 21:36:21.195 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 132 SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,W,107/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.203 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 194 SelectChannelEndPoint@1166e0b{/192.168.1.11:40766<->8080,Open,in,out,-,W,9873/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.208 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1e818f7{IDLE}:WRITING-->IDLE
2017-08-31 21:36:21.211 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@687284[PROCESSING][i=null,cb=Blocker@19c2423{null}] generate: DONE (null,[p=188,l=188,c=32768,r=0],false)@COMMITTED
2017-08-31 21:36:21.211 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@162b713{IDLE}:WRITING-->IDLE
2017-08-31 21:36:21.215 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@179abcc[PROCESSING][i=ResponseInfo{HTTP/1.1 200 null,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1ed55c9] generate: DONE ([p=132,l=132,c=8192,r=0],[p=0,l=0,c=0,r=0],true)@END
2017-08-31 21:36:21.216 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@13dd58a[PROCESSING][i=null,cb=Blocker@bb40ce{null}] generate: FLUSH (null,[p=0,l=188,c=32768,r=188],false)@COMMITTED
2017-08-31 21:36:21.217 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - reset HttpParser{s=END,140 of 140}
2017-08-31 21:36:21.219 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@1f0d786{IDLE} [HeapByteBuffer@7968ab[p=0,l=6,c=1024,r=6]={<<<\r\nBC\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@3b8959[p=0,l=188,c=32768,r=188]={<<<event: message\nda...usInfoEvent"}\n\n>>>"}\n\n\x013\x15"&'.\x0153\x14\x16\x17...\x16\x17\x1e\x01\x17>\x017>\x0135"\x06\x07}]
2017-08-31 21:36:21.219 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - END --> START
2017-08-31 21:36:21.221 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1f0d786{WRITING}:IDLE-->WRITING
2017-08-31 21:36:21.222 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@66551{r=1,c=false,a=IDLE,uri=} handle exit, result COMPLETE
2017-08-31 21:36:21.224 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 194 SelectChannelEndPoint@9b77de{/192.168.1.11:41408<->8080,Open,in,out,-,W,9882/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.225 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled -1 SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,14/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.227 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1f0d786{IDLE}:WRITING-->IDLE
2017-08-31 21:36:21.228 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - ishut SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,Open,in,out,-,-,17/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.229 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@13dd58a[PROCESSING][i=null,cb=Blocker@bb40ce{null}] generate: DONE (null,[p=188,l=188,c=32768,r=0],false)@COMMITTED
2017-08-31 21:36:21.231 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - atEOF HttpParser{s=START,0 of -1}
2017-08-31 21:36:21.233 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@ead712[p=0,l=0,c=8192,r=0]={<<<>>>GET /rest/channel...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-08-31 21:36:21.235 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@687284[PROCESSING][i=null,cb=Blocker@19c2423{null}] generate: FLUSH (null,[p=0,l=135,c=32768,r=135],false)@COMMITTED
2017-08-31 21:36:21.235 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> CLOSED
2017-08-31 21:36:21.238 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@1e818f7{IDLE} [HeapByteBuffer@18677ec[p=0,l=6,c=1024,r=6]={<<<\r\n87\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@b6f3d2[p=0,l=135,c=32768,r=135]={<<<event: message\nda...mStateEvent"}\n\n>>>sDetail\\":\\"NONE\\...\xFf\xF4%\xEfrr\xE3\x86^\x11L\x8cNP\x9e}]
2017-08-31 21:36:21.239 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1e818f7{WRITING}:IDLE-->WRITING
2017-08-31 21:36:21.241 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 141 SelectChannelEndPoint@1166e0b{/192.168.1.11:40766<->8080,Open,in,out,-,W,32/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.241 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1e818f7{IDLE}:WRITING-->IDLE
2017-08-31 21:36:21.243 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@687284[PROCESSING][i=null,cb=Blocker@19c2423{null}] generate: DONE (null,[p=135,l=135,c=32768,r=0],false)@COMMITTED
2017-08-31 21:36:21.245 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@13dd58a[PROCESSING][i=null,cb=Blocker@bb40ce{null}] generate: FLUSH (null,[p=0,l=135,c=32768,r=135],false)@COMMITTED
2017-08-31 21:36:21.246 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@1f0d786{IDLE} [HeapByteBuffer@7968ab[p=0,l=6,c=1024,r=6]={<<<\r\n87\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@3b8959[p=0,l=135,c=32768,r=135]={<<<event: message\nda...mStateEvent"}\n\n>>>sDetail\\":\\"NONE\\...\x16\x17\x1e\x01\x17>\x017>\x0135"\x06\x07}]
2017-08-31 21:36:21.247 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1f0d786{WRITING}:IDLE-->WRITING
2017-08-31 21:36:21.250 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - onClose SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,CLOSED,ISHUT,out,-,-,38/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.252 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - close SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,CLOSED,ISHUT,out,-,-,41/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.253 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Destroyed SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,CLOSED,ISHUT,OSHUT,-,-,42/30000,HttpConnection}{io=0,kio=-1,kro=-1}
2017-08-31 21:36:21.255 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 141 SelectChannelEndPoint@9b77de{/192.168.1.11:41408<->8080,Open,in,out,-,W,29/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.256 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - onClose HttpConnection@1f1725f[FILLING,SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,CLOSED,ISHUT,OSHUT,-,-,44/30000,HttpConnection}{io=0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@66551{r=1,c=false,a=IDLE,uri=}]
2017-08-31 21:36:21.256 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1f0d786{IDLE}:WRITING-->IDLE
2017-08-31 21:36:21.257 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - onClose SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,CLOSED,ISHUT,OSHUT,-,-,45/30000,HttpConnection}{io=0,kio=-1,kro=-1}
2017-08-31 21:36:21.257 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@13dd58a[PROCESSING][i=null,cb=Blocker@bb40ce{null}] generate: DONE (null,[p=135,l=135,c=32768,r=0],false)@COMMITTED
2017-08-31 21:36:21.258 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING-->IDLE HttpConnection@1f1725f[IDLE,SelectChannelEndPoint@18c207d{/192.168.1.11:41429<->8080,CLOSED,ISHUT,OSHUT,-,-,47/30000,HttpConnection}{io=0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@66551{r=1,c=false,a=IDLE,uri=}]
2017-08-31 21:36:21.260 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@687284[PROCESSING][i=null,cb=Blocker@19c2423{null}] generate: FLUSH (null,[p=0,l=192,c=32768,r=192],false)@COMMITTED
2017-08-31 21:36:21.261 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@1e818f7{IDLE} [HeapByteBuffer@18677ec[p=0,l=6,c=1024,r=6]={<<<\r\nC0\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@b6f3d2[p=0,l=192,c=32768,r=192]={<<<event: message\nda...hangedEvent"}\n\n>>>}\n\n.47-.76.34 0 ....\xFf\xF4%\xEfrr\xE3\x86^\x11L\x8cNP\x9e}]
2017-08-31 21:36:21.262 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1e818f7{WRITING}:IDLE-->WRITING
2017-08-31 21:36:21.264 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 198 SelectChannelEndPoint@1166e0b{/192.168.1.11:40766<->8080,Open,in,out,-,W,22/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.265 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1e818f7{IDLE}:WRITING-->IDLE
2017-08-31 21:36:21.267 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@687284[PROCESSING][i=null,cb=Blocker@19c2423{null}] generate: DONE (null,[p=192,l=192,c=32768,r=0],false)@COMMITTED
2017-08-31 21:36:21.270 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@13dd58a[PROCESSING][i=null,cb=Blocker@bb40ce{null}] generate: FLUSH (null,[p=0,l=192,c=32768,r=192],false)@COMMITTED
2017-08-31 21:36:21.272 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@1f0d786{IDLE} [HeapByteBuffer@7968ab[p=0,l=6,c=1024,r=6]={<<<\r\nC0\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@3b8959[p=0,l=192,c=32768,r=192]={<<<event: message\nda...hangedEvent"}\n\n>>>\x013\x15"&'.\x0153\x14\x16\x17\x1e\x0132...\x16\x17\x1e\x01\x17>\x017>\x0135"\x06\x07}]
2017-08-31 21:36:21.274 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1f0d786{WRITING}:IDLE-->WRITING
2017-08-31 21:36:21.276 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 198 SelectChannelEndPoint@9b77de{/192.168.1.11:41408<->8080,Open,in,out,-,W,19/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-08-31 21:36:21.278 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1f0d786{IDLE}:WRITING-->IDLE
2017-08-31 21:36:21.279 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@13dd58a[PROCESSING][i=null,cb=Blocker@bb40ce{null}] generate: DONE (null,[p=192,l=192,c=32768,r=0],false)@COMMITTED
2017-08-31 21:36:22.001 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@164e5a7{/192.168.1.11:37942<->8080,Open,in,out,-,-,30000/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
2017-08-31 21:36:22.008 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@164e5a7{/192.168.1.11:37942<->8080,Open,in,out,-,-,30007/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout expired
2017-08-31 21:36:22.011 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - ignored: WriteFlusher@2d219e{IDLE} java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
2017-08-31 21:36:22.013 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SelectChannelEndPoint@164e5a7{/192.168.1.11:37942<->8080,Open,in,out,-,-,30013/30000,HttpConnection}{io=0,kio=0,kro=1}
13

To me, it looks like you send your notify messages to port 8080, if so, this is wrong
Please set log level for transport.jupnp and WeMo binding to TRACE

14

This is my Java program that emulate WeMo switch (main class):

import java.io.*;
import static java.lang.Thread.sleep;
import java.net.*;

public class MulticastClient {

public static  MulticastSocket socket = null;
public static  InetAddress address2 = null;
public static  int port2 = 8789;
public static  ServerSocket tcpServer = null;
public static  Socket connectionSocket = null;
public static  DatagramPacket pa ;
public static  String bafer = "";
// public static  server = null;
public static  String serijski = "221517K0101707";
public static  String ssid = "904bfa3c-1de2-11v2-8728-fd8eebaf4929";

public static void main(String[] args) throws IOException, InterruptedException
{
    socket = new MulticastSocket(1900); //multicast port
    InetAddress address = InetAddress.getByName("239.255.255.250"); //multicast address
    //address2 = InetAddress.getByName("192.168.1.15");
    socket.joinGroup(address);
    //int port = 1900;
    
    TCPserver tcpServ = new TCPserver(serijski, ssid, port2);
    Thread tr = new Thread(tcpServ);
    tr.start();
    
    while (true) {
        listenUPnP();
    }
    //socket.leaveGroup(address);
    //socket.close();
}

  
public static String listenUPnP() throws IOException, InterruptedException {
    byte[] ulaz = new byte[1024];
    DatagramPacket datPack = new DatagramPacket(ulaz, ulaz.length);
    socket.receive(datPack);
    InetAddress hostAddr = datPack.getAddress();
    int portNumber = datPack.getPort();
    String st = new String(datPack.getData());
    bafer += st;
    address2 = hostAddr;
    //System.out.println(st);
    if ( (st.contains("M-SEARCH")) &&  ( st.contains("ssdp:discover")) ) {
        System.out.println(st);
        InetAddress myIP=InetAddress.getLocalHost();
        System.out.println("UPnP contains word M-SEARCH from address " + hostAddr.getHostAddress() + ":" + portNumber + ", my IP: " + myIP.getHostAddress() + ":" + port2);
        //System.out.println("Host name: "+hostAddr.getHostName() );
        sleep(90);
        System.out.println("-----------------------------------");
        odgovoriNaUPnP(hostAddr, portNumber);
    }
    return st;
}




public static void odgovoriNaUPnP(InetAddress ip, int port) throws IOException {
     System.out.println("We response to UPnP search broadcast!");
     InetAddress myIP=InetAddress.getLocalHost();
     //System.out.println("My IP: " + myIP.getHostAddress());
     String poruka = "HTTP/1.1 200 OK\r\n" ; 
     poruka+= "CACHE-CONTROL: max-age=86400\r\n" ;
     poruka+= "DATE: Wed, 29 Jun 2017 00:13:46 GMT\r\n" ;
     poruka+= "EXT:\r\n" ;
     poruka+= "LOCATION: http://" + myIP.getHostAddress() + ":" + port2 + "/setup.xml\r\n" ;
     poruka+= "OPT: \"http://schemas.upnp.org/upnp/1/0/\"); ns=01\r\n" ;
     poruka+= "01-NLS: " + ssid + "\r\n" ;
     poruka+= "SERVER: Unspecified, UPnP/1.0, Unspecified\r\n" ;
     poruka+= "X-User-Agent: redsonic\r\n" ;
     poruka+= "ST: urn:Belkin:device:controllee:1\r\n" ;                                       // This must be in order to OpenHAB recognise device
     poruka+= "USN: uuid:Socket-1_0-" + serijski + "::urn:Belkin:device:controllee:1\r\n" ;    // This must be in order to OpenHAB recognise device
     //poruka+= "ST: urn:Belkin:device:**\r\n";                                                  // This must be in order to Alexa recognise device
     //poruka+= "USN: uuid:Socket-1_0-" + serijski + "::urn:Belkin:device:**\r\n" ;              // This must be in order to Alexa recognise device
     poruka+= "\r\n" ;
     DatagramPacket zaSlanje = new DatagramPacket(poruka.getBytes(), poruka.length(), ip, port);
     //System.out.println("Poruka: ");
     //System.out.println(poruka);
     socket.send(zaSlanje);
     //DatagramSocket clientSocket = new DatagramSocket();
     //clientSocket.send(zaSlanje);
    }
}

And this is second (server) class:

// If you wish to invoke sending NOTIFY, you nid open your browser and navigate to http://localhost:8789/?something=proba
// When this class receive word "proba" on listen port, method posaljiSubscribe is called


import java.io.BufferedReader;
import java.io.DataInputStream;
import java.io.DataOutputStream;
import java.io.IOException;
import java.io.InputStreamReader;
import java.io.OutputStream;
import java.io.PrintWriter;
import static java.lang.Thread.sleep;
import java.net.ServerSocket;
import java.net.Socket;
import java.net.UnknownHostException;
import java.util.logging.Level;
import java.util.logging.Logger;


public class TCPserver implements Runnable {

    public int port2 = 8789;      // This number will be received from Main class
    ServerSocket tcpServer = null;
    BufferedReader inFromClient = null;
    boolean slanjeGotovo=false;
    public String serijski = "";  // This number will be received from Main class
    public String ssid = "";      // This number will be received from Main class
    private String subscribeUrl;
    private int subsPort = 8080; // This is openHAB listen port, and this should be taken programaticly in the future
    private int izvrseno=0;
    private String subsIP = "192.168.1.105"; // This is openHAB IP, and this should be taken programaticly in the future
    private String subsPath;
    private Socket soc;
    private int seq=0;
    
    
    

    TCPserver(String serij, String SSID, int port) throws UnknownHostException, IOException {
        this.serijski = serij;
        this.ssid = SSID;
        this.port2 = port;
        this.soc = new Socket(this.subsIP, this.subsPort);
    }


    
public String setupXMLNeOvo() {
  String cr=System.getProperty("line.separator");
  String body = "<?xml version=\"1.0\"?>\r\n" ;
  body += "<root xmlns=\"urn:Belkin:device-1-0\">\r\n";
//  body +=  <root xmlns=\"urn:schemas-upnp-org:device-1-0\">\r\n";
  body += "  <device>\r\n";
  body += "    <deviceType>urn:Belkin:device:controllee:1</deviceType>\r\n";
//  body += "    <deviceType>urn:Belkin:device:socket:1</deviceType>\r\n";
//  body += "    <deviceType>urn:Belkin:device:lightswitch:1</deviceType>\r\n";
  body += "    <friendlyName>Svetlo jedan</friendlyName>\r\n";
  body += "    <manufacturer>Belkin International Inc.</manufacturer>\r\n";
  body += "    <modelName>Socket</modelName>\r\n";
  body += "    <modelNumber>3.1415</modelNumber>\r\n";
  body += "    <serialNumber>" + serijski + "</serialNumber>\r\n";
  body += "    <UPC>123456789</UPC>\r\n"; 
  body += "    <UDN>uuid:Socket-1_0-" + serijski + "</UDN>\r\n";
  body += "     <serviceList>\r\n";
  body += "        <service>\r\n";
  body += "           <serviceType>urn:Belkin:service:basicevent:1</serviceType>\r\n";
  body += "           <serviceId>urn:Belkin:serviceId:basicevent1</serviceId>\r\n";
  body += "           <controlURL>/upnp/control/basicevent1</controlURL>\r\n";
  body += "           <eventSubURL>/upnp/event/basicevent1</eventSubURL>\r\n";
  body += "           <SCPDURL>/eventservice.xml</SCPDURL>\r\n";
  body += "        </service>\r\n";
  body += "     </serviceList>\r\n";
  body += "     <presentationURL>/pluginpres.html</presentationURL>\r\n";
  body += "  </device>\r\n";
  body += "</root>";
  //body += "\r\n";

  String header = "HTTP/1.1 200 OK\r\n";
  //String header = "HTTP/1.1\r\n";
  header += "Content-Type: text/xml\r\n";
  header += "Content-Length: " + body.length() + "\r\n";
  header += "DATE: Wed, 29 Jun 2017 00:13:46 GMT\r\n";
  header += "X-User-Agent: redsonic\r\n";
  header += "SERVER: Unspecified, UPnP/1.0, Unspecified\r\n";
  header += "connection: close\r\n";
  header += "LAST-MODIFIED: Tue, 08 Jul 2017 19:20:00 GMT\r\n";
  header += "\r\n";
  header += body;
  
  return header;
}


public String setupXML() {
  String cr=System.getProperty("line.separator");
  String body = "<?xml version=\"1.0\"?>\r\n" ;
  body += "<root xmlns=\"urn:Belkin:device-1-0\">\r\n";
//  body +=  <root xmlns=\"urn:schemas-upnp-org:device-1-0\">\r\n";
  body += "  <device>\r\n";
  body += "    <deviceType>urn:Belkin:device:controllee:1</deviceType>\r\n";
//  body += "    <deviceType>urn:Belkin:device:socket:1</deviceType>\r\n";
//  body += "    <deviceType>urn:Belkin:device:lightswitch:1</deviceType>\r\n";
  body += "    <friendlyName>Svetlo jedan</friendlyName>\r\n";
  body += "    <manufacturer>Belkin International Inc.</manufacturer>\r\n";
  body += "    <modelName>Socket</modelName>\r\n";
  body += "    <modelNumber>3.1415</modelNumber>\r\n";
  body += "    <serialNumber>" + serijski + "</serialNumber>\r\n";
  body += "    <UPC>123456789</UPC>\r\n"; 
  body += "    <UDN>uuid:Socket-1_0-" + serijski + "</UDN>\r\n";
  body += "     <presentationURL>/pluginpres.html</presentationURL>\r\n";
  body += "  </device>\r\n";
  body += "</root>";
  //body += "\r\n";

  String header = "HTTP/1.1 200 OK\r\n";
  //String header = "HTTP/1.1\r\n";
  header += "Content-Type: text/xml\r\n";
  header += "Content-Length: " + body.length() + "\r\n";
  header += "DATE: Wed, 29 Jun 2017 00:13:46 GMT\r\n";
  header += "X-User-Agent: redsonic\r\n";
  header += "SERVER: Unspecified, UPnP/1.0, Unspecified\r\n";
  header += "connection: close\r\n";
  header += "LAST-MODIFIED: Tue, 08 Jul 2017 19:20:00 GMT\r\n";
  header += "\r\n";
  header += body;
  
  return header;
}


public String eventServiceXML() {
  String cr=System.getProperty("line.separator");
  String body;
  String header;
  body  = "<?xml version=\"1.0\"?>\r\n";
  body += "<scpd xmlns=\"urn:Belkin:service-1-0\">\r\n";
  body += "  <specVersion>\r\n";
  body += "    <major>1</major>\r\n";
  body += "    <minor>0</minor>\r\n";
  body += "  </specVersion>\r\n";
  body += "  <actionList>\r\n";
  body += "    <action>\r\n";
  body += "      <name>SetBinaryState</name>\r\n";
  body += "      <argumentList>\r\n";
  body += "        <argument>\r\n";
  body += "          <retval />\r\n";
  body += "          <name>BinaryState</name>\r\n";
  body += "          <relatedStateVariable>BinaryState</relatedStateVariable>\r\n";
  body += "          <direction>in</direction>\r\n";
  body += "        </argument>\r\n";
  body += "      </argumentList>\r\n";
  body += "    </action>\r\n";
  
  body += "    <action>\r\n";
  body += "      <name>GetBinaryState</name>\r\n";
  body += "      <argumentList>\r\n";
  body += "        <argument>\r\n";
  body += "          <retval />\r\n";
  body += "          <name>BinaryState</name>\r\n";
  body += "          <relatedStateVariable>BinaryState</relatedStateVariable>\r\n";
  body += "          <direction>out</direction>\r\n";
  body += "        </argument>\r\n";
  body += "      </argumentList>\r\n";
  body += "    </action>\r\n";
  body += "  </actionList>\r\n";
  
  body += "  <serviceStateTable>\r\n";
  body += "    <stateVariable sendEvents=\"yes\">\r\n";
  body += "      <name>BinaryState</name>\r\n";
  body += "       <dataType>Boolean</dataType>\r\n";
  body += "       <defaultValue>0</defaultValue>\r\n";
 // body += "       <allowedValueRange>\r\n";
 // body += "         <minimum>0</minimum>\r\n";
 // body += "         <maximum>1</maximum>\r\n"; 
 // body += "         <step>1</step>\r\n"; 
 // body += "       </allowedValueRange>\r\n";
  body += "     </stateVariable>\r\n";
  body += "  </serviceStateTable>\r\n";
  body += "</scpd>";
  
  header  = "HTTP/1.1 200 OK\r\n";
  header += "Content-Type: text/xml\r\n";
  header += "Content-Length: ";
  header += body.length();
  header += "\r\n";
  //header += "Date: ";
  header += "DATE: Wed, 29 Jun 2017 00:13:46 GMT\r\n";
  header += "X-User-Agent: redsonic\r\n";
  header += "SERVER: Unspecified, UPnP/1.0, Unspecified\r\n";
  header += "connection: close\r\n";
  header += "LAST-MODIFIED: Tue, 08 Jul 2017 19:20:00 GMT\r\n";
  header += "\r\n";
  header += body;

  return header;  
}
    
  


  
  

public String saljiStatus() {
  String cr=System.getProperty("line.separator");
  String body;
  String header;
  body = "<?xml version=\"1.0\" encoding=\"utf-8\"?>" + cr;
  body += "<s:Envelope xmlns:s=\"http://schemas.xmlsoap.org/soap/envelope/\" s:encodingStyle=\"http://schemas.xmlsoap.org/soap/encoding/\">" + cr;
  body += "<s:Body>" + cr;
  body += "  <u:GetBinaryStateResponse xmlns:u=\"urn:Belkin:service:basicevent:1\">" + cr;
  body += "    <BinaryState>1</BinaryState>" + cr;
  body += "  </u:GetBinaryStateResponse>" + cr;
  body += "</s:Body>" + cr;  
  body += "</s:Envelope>";
  //body += "" + cr;  
  
  header = "HTTP/1.1 200 OK" + cr;
  //header = "HTTP/1.1" + cr;
  header += "CONTENT-TYPE: text/xml; charset=\"utf-8\"" + cr;
  header += "CONTENT-LENGTH: " + body.length() + cr;
  header += "DATE: Mon, 14 Oct 2017 10:58:26 GMT" + cr;
  header += "EXT:" + cr;
  header += "SERVER: Unspecified, UPnP/1.0, Unspecified" + cr;
  header += "connection: close" + cr;
  header += "X-User-Agent: redsonic" + cr;
  header += "" + cr;
  header += body;

  return header;
}


public String potvrdiStanje(int stanje) {
  String cr=System.getProperty("line.separator");
  String body;
  String header;
  body = "<?xml version=\"1.0\" encoding=\"utf-8\"?>" + cr;
  body += "<s:Envelope xmlns:s=\"http://schemas.xmlsoap.org/soap/envelope/\" s:encodingStyle=\"http://schemas.xmlsoap.org/soap/encoding/\">" + cr;
  body += "<s:Body>" + cr;
  body += "  <u:SetBinaryStateResponse xmlns:u=\"urn:Belkin:service:basicevent:1\">" + cr;
  body += "    <BinaryState>" + stanje + "</BinaryState>" + cr;
  body += "  </u:SetBinaryStateResponse>" + cr;
  body += "</s:Body>" + cr;  
  body += "</s:Envelope>";
  //body += "" + cr;  
  
  header = "HTTP/1.1 200 OK" + cr;
  //header = "HTTP/1.1" + cr;
  header += "CONTENT-TYPE: text/xml; charset=\"utf-8\"" + cr;
  header += "CONTENT-LENGTH: " + body.length() + cr;
  header += "DATE: Mon, 14 Oct 2017 10:58:26 GMT" + cr;
  header += "EXT:" + cr;
  header += "SERVER: Unspecified, UPnP/1.0, Unspecified" + cr;
  header += "connection: close" + cr;
  header += "X-User-Agent: redsonic" + cr;
  header += "" + cr;
  header += body;

  return header;
}



private String odgovorNaSubscribe(String primljeno) throws IOException {
  String header, ip, ip1, poo;
  System.out.println("Primljen SUBSCRIBE zahtev:");
  System.out.println(primljeno);
  this.seq = 0;
  //System.out.println("");
  
  header  = "HTTP/1.1 200 OK\r\n";
  header += "DATE: Sun, 11 Jan 2017 18:27:05 GMT\r\n";
  header += "SERVER: Unspecified, UPnP/1.0, Unspecified\r\n";
  header += "CONTENT-LENGTH: 0\r\n";
  header += "X-User-Agent: redsonic\r\n";
  header += "SID: uuid:" + ssid + "\r\n"; 
  //header += "SID: uuid:Socket-1_0-" + serijski + "\r\n";
  header += "TIMEOUT: Second-600\r\n";
  header += "\r\n";
   
  //Callback: <http://192.168.1.105:8080/upnpcallback/dev/Socket-1_0-221517K0101767/svc/Belkin/basicevent1/event/cb>
  int poc, kraj, k1 ;
  poc  = primljeno.indexOf("<http");
  kraj = primljeno.indexOf("cb>");
  kraj = kraj+2;
  //poc = poc+8;
  poc = poc+1;
  ip1 = primljeno.substring(poc, kraj);
  System.out.println("Extracted address: " + ip1);
  k1 = ip1.indexOf(":8080");
  ip = ip1.substring(7,k1);
  k1 = k1+5;
  kraj = ip1.indexOf("/cb");
  kraj = kraj + 3;
  poo = ip1.substring(k1, kraj);
  System.out.println("IP: " + ip);
  this.subscribeUrl = ip1;
  this.subsIP=ip;
  this.subsPath=poo;
  System.out.println("Path: " + poo);
  System.out.println("");

  return header;
}



 

private String posaljiSubscribe(String primljeno) throws IOException, InterruptedException {
    String header;
    String urlParameters ;
    String binState = "0";  // This is what we send as new state of our device. 0 = OFF, 1 = ON
    urlParameters = "";
    //urlParameters = "<?xml version=\"1.0\" encoding=\"utf-8\"?>\r\n";
    //urlParameters += "<?xml version=\"1.0\"?>\r\n";
    urlParameters += "<e:propertyset xmlns:e=\"urn:schemas-upnp-org:event-1-0\">\n";
    urlParameters += "  <e:property>\n";
    urlParameters += "    <BinaryState>" + binState + "</BinaryState>\n";  // Why OpenHAB ignore this value, and always change state to ON, regardles of this value???
    urlParameters += "  </e:property>\n";
    urlParameters += "</e:propertyset>\n\n\r";
  
    header  = "NOTIFY " + "/upnpcallback/dev/Socket-1_0-" + this.serijski + "/svc/Belkin/basicevent1/event/cb HTTP/1.1" + "\r\n";  // Thiss url should be taken from received callback address in SUBSCRIBE request
    header += "HOST: " + this.subsIP + ":" + this.subsPort + "\r\n";
    header += "CONTENT-TYPE: text/xml; charset=\"utf-8\"\r\n";
    header += "CONTENT-LENGTH: " + urlParameters.length() + "\r\n";
    header += "NT: upnp:event\r\n";
    header += "NTS: upnp:propchange\r\n";
    header += "SID: uuid:" + ssid + "\r\n";
    header += "SEQ: " + this.seq + "\r\n";
    //header += "State: 0\r\n";
    //header += "TYPE: socket\r\n";
    //header += "ID: " + this.serijski + "\r\n";
    header += "\r\n";
    header += urlParameters;
    
    sleep(20);
    if (this.soc.isClosed()) soc = new Socket(this.subsIP, this.subsPort);
    PrintWriter pout = new PrintWriter(soc.getOutputStream(), true);
    InputStreamReader isr = new InputStreamReader(soc.getInputStream());
    BufferedReader bfr = new BufferedReader(isr);
    pout.println(header);
    System.out.println(header);
    //System.out.println("");
    pout.flush();
    sleep(50);

    System.out.println("Response:");
    String odg = bfr.readLine();
    System.out.println(odg);
    odg = bfr.readLine();
    System.out.println(odg);
    odg = bfr.readLine();
    System.out.println(odg);
    odg = bfr.readLine();
    System.out.println(odg);
    odg = bfr.readLine();
    System.out.println(odg);
    pout.close();
    soc.close();
    this.seq++;
    slanjeGotovo=true;
    return header;
}




private void odlucivanje(String paket) {
    //System.out.println("Rutina za obradu primljenog paketa. Primljeno:");
    //System.out.println(paket);
}



@Override
public void run() {
        try {
            String clientSentence;
            String prijem = "";
            ServerSocket tcpServer1 = new ServerSocket(port2);
            System.out.println("");
            
            
            while (true) {
                //System.out.println("----------- Start of cycle ----------");
                try {
                    int a=1;
                    slanjeGotovo=false;
                    Socket connectionSocket = tcpServer1.accept();
                    OutputStream os = connectionSocket.getOutputStream();
                    DataOutputStream outToClient = new DataOutputStream(os);
                    InputStreamReader isr = new InputStreamReader(connectionSocket.getInputStream());
                    inFromClient = new BufferedReader(isr);
                      DataInputStream in = new DataInputStream(connectionSocket.getInputStream());
                      byte[] messageByte = new byte[1000];
                      int bytesRead=0;
                      String messageString = "";

                      while (bytesRead>=0) {
                          bytesRead = in.read(messageByte);
                          if(bytesRead>0) messageString += new String(messageByte, 0, bytesRead);
                          prijem = messageString;
                          //System.out.println("NOVA RUTINA PRIMILA: " + messageString);
                          odlucivanje(messageString);
                          break;
                      }
                     
                    clientSentence = "xx";
                    if (clientSentence != null) {
                        if (prijem.contains("setup.xml")) {
                            prijem="";
                            //saljiSetupXml();
                            System.out.println("Šaljem setup.xml");
                            System.out.println("");
                            sleep(50);
                            outToClient.writeBytes(setupXMLNeOvo());
                            outToClient.flush();
                            slanjeGotovo=true;
                        }
                        
                        if (prijem.contains("eventservice.xml")) {
                            prijem="";
                            System.out.println("Saljem eventservice.xml");
                            sleep(10);
                            outToClient.writeBytes(eventServiceXML());
                            outToClient.flush();
                            slanjeGotovo=true;
                        }
                        
                        if ( (prijem.contains("POST")) && (prijem.contains("basicevent1")) &&  (prijem.contains("GetBinaryState")) && (prijem.contains("Envelope")) ) {
                            prijem="";
                            //System.out.println("Requested basicevent1 - GetBinaryState");
                            System.out.println("Sending state");
                            //System.out.println("");
                            sleep(2);
                            outToClient.writeBytes(saljiStatus());
                            outToClient.flush();
                            //System.out.println(saljiStatus());
                            //System.out.println("");
                            slanjeGotovo=true;
                        }

                        if (prijem.contains("proba") || (prijem.contains("1#GetBinaryState") && (prijem.contains("Envelope>")) ) ) {
                            prijem="";
                            if (this.izvrseno==0) {
                                System.out.println("Šaljem Subscribe!!!");
                                posaljiSubscribe("");
                            }
                            this.izvrseno++;
                            if (this.izvrseno>11) this.izvrseno=0;
                            slanjeGotovo=true;
                        }
                        
                        if (prijem.contains("<BinaryState>1</BinaryState>") ) {
                            prijem="";
                            sleep(5);
                            System.out.println("Turning ON");
                            outToClient.writeBytes(potvrdiStanje(1));
                            outToClient.flush();
                            slanjeGotovo=true;
                        }
                        if (prijem.contains("<BinaryState>0</BinaryState>") ) {
                            prijem="";
                            sleep(5);
                            System.out.println("Turning OFF");
                            outToClient.writeBytes(potvrdiStanje(0));
                            outToClient.flush();
                            slanjeGotovo=true;
                        }
                        
                        //if ( prijem.contains("SUBSCRIBE") && prijem.contains("jUPnP") ) {
                        if ( prijem.contains("SUBSCRIBE") && prijem.contains("Keep-Alive") ) {
                            outToClient.writeBytes(odgovorNaSubscribe(prijem));
                            //odgovorNaSubscribe(prijem);
                            outToClient.flush();
                            System.out.println("Reply to SUBSCRIBE sent out");
                            // System.out.println(odgovorNaSubscribe(prijem));
                            //System.err.println("");
                            prijem="";
                            slanjeGotovo=true;
                        }
                        
                        if (!prijem.isEmpty()) slanjeGotovo=true; 
                    }
                    else { // if input string is null
                        System.err.println("Received null");
                    }
                    while (!slanjeGotovo) {
                        //
                        if ( (clientSentence == null) ) break;
                        //if ( (clientSentence.contains("keep-alive")) ) slanjeGotovo=true;
                        System.out.println("Wait for sending ends...");
                        sleep(10);
                    }
                    
                    os.flush();
                    outToClient.flush();
                    sleep(20);
                    os.close();
                    outToClient.close();
                    connectionSocket.close();
                    prijem="";
                    //System.out.println("Comm ch closed");
                    //System.out.println("----------- Kraj ciklusa ----------");
                    //System.out.println("");
                } catch (        IOException | InterruptedException ex) {
                    Logger.getLogger(TCPserver.class.getName()).log(Level.SEVERE, null, ex);
                }
            }
        } catch (IOException ex) {
            Logger.getLogger(TCPserver.class.getName()).log(Level.SEVERE, null, ex);
        }
}
    
}
15

Yes, to port 8080. I mean, that port is openHAB send to my switch, as request to receiving NOTIFY?
This is what i receive from openHAB (every 10 minutes):

SUBSCRIBE /upnp/event/basicevent1 HTTP/1.1
Nt: upnp:event
Timeout: Second-600
Callback: <http://192.168.1.105:8080/upnpcallback/dev/Socket-1_0-221517K0101707/svc/Belkin/basicevent1/event/cb>
Host: 192.168.1.11:8789
Connection: Keep-Alive
User-Agent: Linux/4.9.35-v7 UPnP/1.0 jUPnP/2.0

If i need to set another port to sending NOTIFY, other 8080 (which is quoted in callback line), please help me to determine on which port i need to send NOTIFY?

An one more question: Please, help me, which command i shoult to issue for set log level for transport.jupnp and WeMo binding to TRACE? I’m not familiar with console :frowning:

16

OK, so port seems to be correct.
Loglevel is set by

log:set TRACE org.jupnp
log:set TRACE org.eclipse.smarthome.binding.wemo
17

OK, seems to loging work well :slight_smile: Thank you!
But, file is too big for sending here, can you, please, download log from my GoogleDrive?

https://drive.google.com/file/d/0B2CGvD0KNZYQZ3JlZVpWYVZ1ODQ/view?usp=sharing

Sorry for that :frowning:

18

I found, in the log, line 172:

2017-08-31 22:06:19.414 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Received pair 'BinaryState':'false' (service 'basicevent1') for thing 'wemo:socket:Socket-1_0-221517K0101707'

It seems to wemo binding recognise false state (as i send) but i don’t know why then state of the button (in the paper-UI) is set to ON???

20

I just copy another log

https://drive.google.com/drive/folders/0B2CGvD0KNZYQbjN5Zk9JcjJ2Y3M?usp=sharing

21

Sorry, but you are misinterpreting the log.

If you look into the code of wemo binding, you will find the following:

            State state = stateMap.get("BinaryState").equals("0") ? OnOffType.OFF : OnOffType.ON;

Anything received but a ZERO will be interpreted as ON.

So, we need to figure out, why JUPnP sends "BinaryState:false to the wemo binding.

Please try the following, in

private String posaljiSubscribe

change

    urlParameters += "  <e:property>\n";
    urlParameters += "    <BinaryState>" + binState + "</BinaryState>\n";  // Why OpenHAB ignore this value, and always change state to ON, regardles of this value???
    urlParameters += "  </e:property>\n";

to

    urlParameters += "  <e:property>\r\n";
    urlParameters += "    <BinaryState>" + binState + "</BinaryState>\r\n"
    urlParameters += "  </e:property>r\n";

This is the only difference I see in my Wireshark capture.