openHAB 2.0 binding

Denke

@meju25 I saw this from a management perspective.
I have one device, my pool controller, that has multiple sensors and also channels per sensor just as HVAC that has a sum of channels. In my case i implemented a number of sensors in different types of channels "S_HVAC, S_LIGHT,...." what i see that it gets messy when you try to see if the channels are active or the pool control is active it has multiple sensors.

So maybe a suggestion is to maybe implement this in the mysensors instead of in the openhab binding.
In that case i would like to add something that allows me to tell what channels are in a "sensor" by combining differnt channels and sensor types.

I don't know if i got my message through.

But all this is mainly for management of my devices so that this gets less messy

dakky

@TimO do you plan to implement the reconnect thing? I often have to struggle with that and the only solution is the restart the openhab service :S Is there a problem with the reconnect or is it just "another task on the todo list"?

Greetings
Dakky

Denke

Hi
Is there anybody that have had a problem with the S_BARO and the V_PRESSURE channel?

I try to send a value on this channel as 1.2 I can see that the serial gateway receives it

23:10:51.808 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;0;3;0;9;read: 163-163-0 s=10,c=1,t=4,pt=7,l=5,sg=0:1.2

I set up the channel as i have done for alot of other channels through the paper ui. where i link the channel to an item.

The item file looks like this
String Pool_Pressure "Pressure [%s]" <pressure> (gPool)

the sitemap file looks like this
Text item=Pool_Pressure

result is this
0_1466111768156_upload-9d8b8d90-c258-4979-b27f-0162a9ffcdc5

The field never gets updated.
any suggestions?

Denke

@Denke
I cant find V_PRESSURE connected to CHANNEL_BARO below, can that be the reason?

0_1466112268981_upload-f457bebe-d1b9-41d0-9f82-a7c55307e5d5

TimO

@Denke : You're right, the pressure channel was missing in the thing definition. This is fixed in the current version!

@dakky : Which gateway type keeps disconnecting and why? I've a serial and ethernet gateway running side by side in OH2 and both didn't get disconnected so far. The hardest part is to recognize if the connection gets down.

gonzalonal

Hi @TimO . Are you having both gateways connected to same the OH simultaneously?
Any troubles with that? I imagine you should have different radio channels for each gateway, right? like two separate sensors networks.

TimO

Hi @gonzalonal !

Only the ethernet gateway has an attached radio.

Here is my current (MySensors) setup:

Bridge mysensors:bridge-eth:MySGW [ ipAddress="192.168.2.99", tcpPort=5003, sendDelay=100, skipStartupCheck=true  ] {
	humidity        bathHum01   			[ nodeId="101", childId="0" ]
    temperature     bathTemp01  			[ nodeId="101", childId="1" ]
    humidity		bathBat01				[ nodeId="101", childId="255" ]
    
    
    humidity        bedHum01   				[ nodeId="103", childId="2" ]
    temperature     bedTemp01  				[ nodeId="103", childId="1" ]
    humidity		bedBat01				[ nodeId="103", childId="255" ]
    
    humidity        workHum01  				[ nodeId="104", childId="2" ]
    temperature     workTemp01 				[ nodeId="104", childId="1" ]
    humidity		workBat01				[ nodeId="104", childId="255" ]
    
    humidity        kitchenHum01			[ nodeId="105", childId="2" ]
    temperature     kitchenTemp01			[ nodeId="105", childId="1" ]
	humidity		kitchenBat01			[ nodeId="105", childId="255" ]
    
    humidity        childHum01 				[ nodeId="107", childId="3" ]
    temperature     childTemp01				[ nodeId="107", childId="4" ]
    light			childLight01			[ nodeId="107", childId="0" ]
    light			childLight02			[ nodeId="107", childId="1" ]
    light			childLight03			[ nodeId="107", childId="2" ]
    
    humidity        guestHum01				[ nodeId="106", childId="0" ]
    temperature     guestTemp01				[ nodeId="106", childId="1" ]
	light			guestPresence01			[ nodeId="106", childId="3" ]
    light			livingLight01			[ nodeId="106", childId="4" ]
    light			livingLight02			[ nodeId="106", childId="5" ]
    light			livingLight03			[ nodeId="106", childId="6" ]
    light			livingLight04			[ nodeId="106", childId="7" ]
    light			corridorLight03			[ nodeId="106", childId="8" ]
    light			livingLight06			[ nodeId="106", childId="9" ]
    
    humidity        livingHum01				[ nodeId="108", childId="2" ]
    temperature     livingTemp01			[ nodeId="108", childId="1" ]
	humidity		livingBat01				[ nodeId="108", childId="255" ]
	
	humidity        gardenHum01				[ nodeId="110", childId="2" ]
    temperature     gardenTemp01			[ nodeId="110", childId="1" ]
	humidity		gardenBat01				[ nodeId="110", childId="255" ]
	motion			gardenMotion01			[ nodeId="110", childId="3" ]
    
}

Bridge mysensors:bridge-ser:MySGWKeller [ serialPort="/dev/ttyUSB0", sendDelay=100, skipStartupCheck=true ] {
    cover			kitchenShutter02 	[ nodeId="0", childId="0" ]
    cover			kitchenShutter03	[ nodeId="0", childId="1" ]
    cover			livingShutter01 	[ nodeId="0", childId="2" ]
    cover			livingShutter02 	[ nodeId="0", childId="3" ]
    cover			kitchenShutter01 	[ nodeId="0", childId="4" ]
    light			corridorLight01		[ nodeId="0", childId="5" ]
    light			corridorLight02		[ nodeId="0", childId="6" ]
    power			corridorLight01watt	[ nodeId="0", childId="7" ]
}

dakky

@TimO

I'm using a ethernet gateway.
the problem is: if the sensors gateway gets restarted/disconnected/updated/whatever the binding does not reconnect. The only way to fix that, is to restart openhab in order to force the binding to connect again.
Detecting an disconnect is really that hard? in the worst case, what about simply reconnecting timebased? not as cute as only reconnect when nessecary but a dirty quickfix.

gonzalonal

Thanks @TimO. Now I get it.
What do you think about having two gateways, one with NRF radio and the other one with RFM69 radio?

Will the binding support both gateways simultaneusly with no issues?

Another question..Will you support HearbeatRequest for the development branch?

Thanks, regards.

gonzalonal

Hello againg.

I have updated my OH2 to latest nightbuild from cloudbees, and also updated to lastest realease of OH2 MyS Binding.

Now, I am facing an issue, that everytime that OH2 starts, it sends out all the items status to its respective node. This is causing, for example, to open my gates, or lowering my rollershutters, even disabling/enabling my alarm system. So I have shutdown OH2 for time being.

Have anyone faced this behavior before?

This is some of the log:

15:41:40.241 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'mysensors:bridge-ser:gateway' takes more than 5000ms.
15:41:40.272 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.295 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.322 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.335 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.348 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.362 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.375 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.388 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.402 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.545 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Home.items'
15:41:40.671 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.685 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.697 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.710 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.724 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.738 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.755 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.768 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.783 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.806 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;14;Gateway startup complete.
15:41:40.811 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.856 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.871 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.885 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.898 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.914 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.928 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:40.941 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:41.029 [DEBUG] [g.mysensors.protocol.MySensorsWriter] - Sending to MySensors: 2;3;1;0;0;
15:41:41.110 [DEBUG] [g.mysensors.handler.MySensorsHandler] - handleCommand called
15:41:41.288 [DEBUG] [g.mysensors.protocol.MySensorsWriter] - Sending to MySensors: 3;253;1;0;2;
15:41:41.546 [DEBUG] [g.mysensors.protocol.MySensorsWriter] - Sending to MySensors: 1;6;1;0;2;
15:41:41.799 [DEBUG] [g.mysensors.protocol.MySensorsWriter] - Sending to MySensors: 3;252;1;0;24;REFRESH
15:41:42.052 [DEBUG] [g.mysensors.protocol.MySensorsWriter] - Sending to MySensors: 3;254;1;0;2;
15:41:42.307 [DEBUG] [g.mysensors.protocol.MySensorsWriter] - Sending to MySensors: 1;254;1;0;2;
15:41:42.562 [DEBUG] [g.mysensors.protocol.MySensorsWriter] - Sending to MySensors: 3;3;1;0;2;
15:41:42.817 [DEBUG] [g.mysensors.protocol.MySensorsWriter] - Sending to MySensors: 1;253;1;0;2;
15:41:43.073 [DEBUG] [g.mysensors.protocol.MySensorsWriter] - Sending to MySensors: 2;252;1;0;24;REFRESH

I would really appreciate your help.

TimO

@gonzalonal I have no idea why this should happen. The binding isn't that smart to do something like that. I've done a complete fresh installation on 21.06. with the nightly build from cloudbees and don't see this issue.

@dakky Do you see disconnection messages in the log? The binding already tries to detect a disconnect and tries to reestablish the connection when an ethernet gateway is used. Currently the time within a reconnect would be successful is very small due to sleep limitations of threads in OH2 bindings.

gonzalonal

Thanks @TimO . I will try to make a progressive installation and try to figure out what is causing this behavior.

I'll let you know if I find out.
Have you read my previous message?
Regards

@gonzalonal said:

Thanks @TimO. Now I get it.
What do you think about having two gateways, one with NRF radio and the other one with RFM69 radio?

Will the binding support both gateways simultaneusly with no issues?

Another question..Will you support HearbeatRequest for the development branch?

Thanks, regards.

TimO

@gonzalonal : I just downloaded the recent version of the binding again and I don't see this behaviour.

I hope both gateways will work together! This is was the idea. I've not tested it in combination with RFM69 but I don't see a reason why this should not work!

gonzalonal

@TimO I have solved my probles using OH2 Beta3 and the last release of the MyS binding.

It seems that the problem is only reproduced with the last release of OH2 from Cloudbees. At least withe the release 372.

Have you tryed it?

kolaf

After a full computer crash (overheated CPU, CPU fan stopped working) I'm trying to set everything up on a new computer. Using the latest openhab2 beta 3 I'm having issues with using this binding. Specifically, whenever I add my standard thing configuration I get a buffer overflow in openhab which results in a core dump.

I have downloaded latest binding from the link at github, but that did not affect it. In addition to this binding I am using the zwave binding and rfxcom binding. All three connect to devices through serial ports, although I I'm not sure if they do it in the same way.

You may recall that I have had trouble using these three bindings together earlier, but for some reason things worked out and it has worked quite reliably since then.

I'm not sure which information from the system crash is useful, but if there is anything I can send you to help you figure out what happens, let me know. Also, I realise that this problem might not be related directly with mysensors, but maybe with the serial library used (I saw a reference to NVJavaSeria in the stack trace after the crash.

kolaf

Hello again.

As a temporary fix I found a simple TCP/serial Gateway Python snippet that handles the connection to the serial mysensors device and provides a TCP interface to openhab. Switching the binding of aggression from serial to socket and having it connected to this software gateway removes the core dump issue. This confirms my suspicions that the issues are with the serial port library.

It works okay as a workaround until someone figure something out

If anyone else is having issues with the serial connection, this is the by then snippet I found and used:

https://github.com/pyserial/pyserial/blob/master/examples/tcp_serial_redirect.py

TimO

@kolaf I'm only using one serial gw and that is running rock stable within OH2. My last update was 22 days ago, so maybe it is time for an update again.

I recently changed my job, so I'm a little low in time at the moment.

Fredrik Jönsson

From what i can see this binding is not part of the official bindings for openHAB. Are there any plans to try to get this as a official binding for openhab?

/Fredrik

TimO

@Fredrik-Jönsson : Yes, this is on my to do list with high priority. I've done some preparations but need to contact the OH2 developers before creating a PR.

TimO

@gonzalonal :

I've found the time to sync my repository with upstream master OH2. Now I do see the behaviour you described above. The status of every item is send out at startup.

Using the current package of the MySensors binding from today with an older version of OH2 does work fine. But my development environment now throws out the status of all things.

Are you using any other bindings? Are they working fine?At first I need to find out if this problem only occures with the MySensors binding or if there is a bug.

gonzalonal

Hi @TimO.
I am using several bindings in my OH2 setup.
As I am using MyS and OH2 in a productive and sensible environement I could try out how the other bindings behaved. As soon as I detect the error I had to rollback my setup. So I can't really tell is there is a bug with the latest snapshot of OH2 or if it is something more specific of MyS binding.

I am currently using OH2 Beta 3 with no issues.

Fredrik Jönsson

@TimO That sounds great, i will start trying this out. By reading this thread it sounds like it works quite well..

Thanks for all you time you put into this binding.

/Fredrik

TimO

@gonzalonal : I've found the reason for this beaviour and fixed the bug.

@andreacioni contributed a PR to the code that includes a channel for the last update of a thing. If you want to know at which time there was a message from a node you may subscribe to the "lastupdate" channel.

Example:

DateTime   lastUpdate01 "Last Update" { channel="mysensors:baro:gateway:baro01:lastupdate" }

Thanks @andreacioni !

gonzalonal

Hi @TimO .
I have tried the binding and the issue is fixed as you have said.
I have been looking at the logs, and found the following regarding last update feature:

15:52:11.580 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 1;253;1;0;2;1
15:52:11.583 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.581-0300
15:52:11.585 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.584-0300
15:52:11.590 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.588-0300
15:52:11.594 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.592-0300
15:52:11.598 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.597-0300
15:52:11.602 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.601-0300
15:52:11.606 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.604-0300
15:52:11.609 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.608-0300
15:52:11.613 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.611-0300
15:52:11.618 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.616-0300
15:52:11.624 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.622-0300
15:52:11.628 [DEBUG] [g.mysensors.handler.MySensorsHandler] - Setting last update for node 1 to 2016-08-08T15:52:11.626-0300

Is this the expected behavior? It seems to me that we should have only one "Setting last.." for value updated.
Maybe is my setup. Can someone check this.
Thanks!

andreacioni

Hi @gonzalonal

The implementation of the binding create a thing for every channel of a single node. So the solution result is what you can see in the log. We can do a little bit more to prevent a single message to fire every 'lastupdate' channel of every thing that have the same node ID. But I think it is not a good idea.

gonzalonal

Got it!
Thanks for your quick reply @andreacioni

Gustafsson

Hi guys,

I've tried to add my ethernet gateway to openhab2 through but I just cant get the Online-status on, it. Do I have to do anything else than just adding it into the things file?

andreacioni

Hi @Gustafsson,

Have you read the readme? Readme . Probably you have not configured things? See the readme on how to do that

Gustafsson

@andreacioni That's exactly what I did.

Things

Bridge mysensors:bridge-eth:gateway [ ipAddress="192.168.254.228", tcpPort=5003, sendDelay=200 ]
        door    frontDoor       [ nodeId="102", childId="4" ]
}

Items

Text    frontDoor       "Door"  { channel="mysensors:door:gateway:frontDoor:tripped" }

Sitemap

sitemap MySitemap label="Main Menu" {
        Frame {
                Text item=frontDoor
        }
}

This is how everything looks like now. I get the door item green in habmin but still the red cross on the gateway. The door item dosn't show me if it's open or closed.

gonzalonal

@Gustafsson

You are missing the opening brackets

Bridge mysensors:bridge-eth:gateway [ ipAddress="192.168.254.228", tcpPort=5003, sendDelay=200 ] {
door frontDoor [ nodeId="102", childId="4" ]
}

Gustafsson

@gonzalonal sorry, I missed it when I pasted in my code here, so there is in fact a { in my code. Any other ideas?

FutureCow

I have a problem with adding one of my nodes.
My temp en hum nodes are working perfectly, but i try to add a Light Level node. The sensor is sending the amount of Lux and not the percentage:

18:14:59.572 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 1-1-0 s=0,c=1,t=23,pt=3,l=2,sg=0:3
18:14:59.572 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 1;0;1;0;23;3
18:14:59.574 [ERROR] [g.mysensors.protocol.MySensorsReader] - (java.lang.IllegalStateException: Could not update state, because callback is missing) on reading from serial port, message: class org.openhab.binding.mysensors.protocol.serial.MySensorsSerialReader

It is using CHILD_ID_LIGHT inside the skechts. Is this light level node supported?

TimO

@FutureCow said:

18:14:59.572 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 1;0;1;0;23;3

According to this: https://www.mysensors.org/download/serial_api_20

V_LIGHT_LEVEL	23	Uncalibrated light level. 0-100%. Use V_LEVEL for light level in lux.	S_LIGHT_LEVEL
V_LEVEL	37	Used for sending level-value	S_DUST, S_AIR_QUALITY, S_SOUND (dB), S_VIBRATION (hz), S_LIGHT_LEVEL (lux)

Your node should send "1;0;1;0;37;3 if I'm not mistaken.

The light level message is supported by the binding.

TimO

Small update to the progress:

Expert mode: I've added a special thing that will allow rule based parsing and sending of MySensors messages. If the binding is limiting your creativity you are now free to go. You are now able to combine/adapt rules like in this Thread with the easy process of thing/item/sensor configuration. I've added a description to the Wiki. This may solve some problems mentioned above with sensors requesting information like pulse count.
Last week the OH2 core team has released beta4 of OH2. I've tested the binding against the current beta and it is working fine.
I've created a PR against the official openhab2-addons repository. I'm now awaiting feedback and hope to introduce the MySensors binding as part of OH2.

hek

Great job @Timo!

gonzalonal

Great news to hear @TimO .
I will be testing the binding in a couple of hours. It's really usefull the new RAW messenger things.
Thanks!

xlibor

Hi all, i am new in mysensors, but i have problem with install this plugin to OpenHab2.0 i tried versions 2.0 and 2.0b4 but i couldn't see this plugin in OpenHab2, i tried with RPi B, RPi3 with Raspian Jessie, and with Windows 10. But all with the same result.

I placed org.openhab.binding.mysensors-2.0.0.SNAPSHOT.jar into addons directory, but i can't se it in OpenHab.

Can anyone help me?

TimO

@xlibor Did you follow the instructions on the wiki and installed serial transport first? Is there a log file entry? How did you install OH2? Debian Package or Zip File?

xlibor

This post is deleted!

xlibor

@TimO Yes, i follow instruction on wiki and install serial transport sucesfully. I tried both types, first zip file and next package, but both with the same result

In log file is nothing about mysensors or any error.

Now i downloaded again from github and now all works without any problem. But i don't know where was problem.

daxjones

Hey All. Newbie alert here. I love the work you all do on here and this project is so exciting. I'm hooked after 2 weeks of 'fettling' and building sensors.

I've hit a brick wall though. after struggling with openhab1 I decided to make the leap straight to openhab2. Although in early days of testing it seems immediately abit more user friendly.

What I've done so far...
RaspberryPi3 is acting as controller with openhab2 installed and running fine. bindings to TV and Nest thermostat all working lovely.

Clone arduino Uno's with capacitors added for radio with NRF24 radio cards

Created GatewayW5100 gateway using the mysensors library sketch for it and set static IP to 192.168.0.11 (Openhab2 is set to 192.168.0.10) and my router gives DHCP from 192.168.0.20 up

created a temp and humidity sensor node and a node with a relay to turn a lamp on (both from mysensors library). Tested radio on all before moving ahead.

Installed the mysensors binding on OH2

Added a ethernet gateway

disabled startup connection check as it kept failing to initialise and showed as offline

Tried auto discovery of nodes... NOTHING

Tried setting node ID manually on the arduinos.. Still NOTHING, even if i add a thing manually to OH2.

I'm hoping i'm doing something stupid and its an easy fix.. Any pointers for a newbie??

D.

TimO

@daxjones

Have you tried to reach your gateway with telnet?

telnet 192.168.2.11 5003

Does it respond? Do you see the messages from the node arriving?

Have you enabled debug output of the binding like described in the wiki? What does the log say?

Fleischtorte

Hi@TimO

first, thanks for your awesome work
On the weekend i switched from OH1 to OH2 and your binding is working just out of the box
Im only missing the IR_Send and the V_TEXT sensor to integrate all of my sensors
could you integrate them in your binding?

TimO

Thanks @Fleischtorte!

There already was a request for IR and I've added one for V_TEXT.

https://github.com/tobof/openhab2-addons/issues

@andreacioni has done some serious refactoring of the code. After looking in the refactoring I'll add the missing sensors.

Meshx86

I have the following setup:

MQTT Gateway on Wemos D1 mini (ESP8266)
Node on Arduin pro mini

i can't get the openhab binding to distribute address to the nodes, in things in openhab there is no option for MQTT Gateway to add, what is the procedure ?

Cheers

Qu3Uk

@Meshx86 the openhab binding doesnt support MQTT as far as I know.

If you are using the MQTT binding then you need another controller/method to provide the internal functions for my sensors. I use NodeRed workflow to listen for ID requests and it provides them.

Or static assign them in the node stretch.

carlyler

@TimO: Thanks to you this weekend, while kids slept or napped, I managed to setup RPi gateway/controller with NRF24 and OH2.
Following the OH2 install instructions caused me some trouble, not sure why, but following your install instructions it came right up.
Thank you for the time and effort here.

carlyler

Having a couple issues:

while adding 2nd node (tried power and temp/hum) OH2 would not assign node ID.
assigned node ID manually (ID=2) and OH2 recognized power node but will not respond to V_VAR1 request.

16:23:58.850 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;1;1;0;0;20.4
16:23:58.874 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;0;1;0;1;47.3
16:24:01.910 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
16:24:09.293 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;0;1;0;1;47.5
16:24:11.911 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
16:24:11.942 [DEBUG] [rs.internal.protocol.MySensorsReader] - 2;0;2;0;24;
16:24:19.736 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;0;1;0;1;47.7
16:24:21.912 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
16:24:26.987 [DEBUG] [rs.internal.protocol.MySensorsReader] - 2;0;2;0;24;
16:24:30.177 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;0;1;0;1;47.6
16:24:31.913 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
16:24:40.604 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;0;1;0;1;47.5
16:24:41.914 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
16:24:42.044 [DEBUG] [rs.internal.protocol.MySensorsReader] - 2;0;2;0;24;
16:24:51.916 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
16:24:57.102 [DEBUG] [rs.internal.protocol.MySensorsReader] - 2;0;2;0;24;
16:25:01.917 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
16:25:11.919 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
16:25:12.145 [DEBUG] [rs.internal.protocol.MySensorsReader] - 2;0;2;0;24;
16:25:21.921 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
16:25:22.304 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;0;1;0;1;47.6

Things:

Bridge mysensors:bridge-ser:gateway [ serialPort="/dev/pts/2", sendDelay=200 ] {
   /** define things connected to that bridge here */
   humidity        hum01   [ nodeId="1", childId="0" ]
   temperature     temp01  [ nodeId="1", childId="1" ]
   power           power01 [ nodeId="2", childId="0" ]
}

Items:

Number hum01   "Humidity"              <humidity> { channel="mysensors:humidity:gateway:hum01:hum" }
Number temp01  "Temperature"           <temperature> { channel="mysensors:temperature:gateway:temp01:temp" }
Number temp01F "Temperature [%.1f °F]" <temperature>
DateTime Sensor01LastUpdate "Last seen [%1$ta %1$tR]" <clock>
DateTime Sensor02LastUpdate "Last seen [%1$ta %1$tR]" <clock>
Number watt01  "Current Demand [%.0f Watt]" { channel="mysensors:power:gateway:power01:watt" }
Number kwh01  "Daily Use [%.1f kWh]"        { channel="mysensors:power:gateway:power01:kwh" }

What am i doing wrong?

carlyler

OK, I think I got past that, I reinstalled everything and cleaned up my MySensors libraries.There is a chance I was pulling from different version when compiling the different examples from different packages.

But, I noticed this exception at OH2 startup:

06:29:26.838 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:gateway' changed from UNINITIALIZED to INITIALIZING
06:29:26.924 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 1, chiledId: 1, revertState: false
06:29:26.924 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 1, chiledId: 0, revertState: false
06:29:26.932 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 2, chiledId: 0, revertState: false
06:29:26.951 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:gateway:hum01' changed from UNINITIALIZED to INITIALIZING
06:29:26.946 [DEBUG] [col.serial.MySensorsSerialConnection] - Set skip check on startup to: false
06:29:26.956 [DEBUG] [col.serial.MySensorsSerialConnection] - Enabling connection watchdog
06:29:26.964 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temp01' changed from UNINITIALIZED to INITIALIZING
06:29:26.969 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:power:gateway:power01' changed from UNINITIALIZED to INITIALIZING
06:29:26.993 [DEBUG] [ternal.factory.MySensorsCacheFactory] - Cache file: given_ids.cached exist.
06:29:27.001 [DEBUG] [col.serial.MySensorsSerialConnection] - Connecting to /dev/pts/3 [baudRate:115200]
06:29:27.032 [DEBUG] [ternal.factory.MySensorsCacheFactory] - Cache (given_ids) content: []
06:29:27.067 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:gateway' changed from INITIALIZING to UNINITIALIZED (HANDLER_INITIALIZING_ERROR)
06:29:27.041 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while initializing handler of thing 'mysensors:bridge-ser:gateway': java.lang.UnsupportedOperationException
java.util.concurrent.ExecutionException: java.lang.UnsupportedOperationException
	at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_65]
	at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_65]
	at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:186)[99:org.eclipse.smarthome.core:0.9.0.201610220816]
	at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:79)[99:org.eclipse.smarthome.core:0.9.0.201610220816]
	at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:63)[99:org.eclipse.smarthome.core:0.9.0.201610220816]
	at org.eclipse.smarthome.core.thing.internal.ThingManager$9.run(ThingManager.java:755)[106:org.eclipse.smarthome.core.thing:0.9.0.201610220816]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_65]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_65]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_65]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0_65]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_65]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_65]
	at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]
Caused by: java.lang.UnsupportedOperationException
	at java.util.AbstractList.add(AbstractList.java:148)[:1.8.0_65]
	at java.util.AbstractList.add(AbstractList.java:108)[:1.8.0_65]
	at org.openhab.binding.mysensors.internal.handler.MySensorsBridgeHandler.loadCacheFile(MySensorsBridgeHandler.java:176)[10:org.openhab.binding.mysensors:2.0.0.201610021604]
	at org.openhab.binding.mysensors.internal.handler.MySensorsBridgeHandler.initialize(MySensorsBridgeHandler.java:90)[10:org.openhab.binding.mysensors:2.0.0.201610021604]
	at org.eclipse.smarthome.core.thing.internal.ThingManager$9$1.call(ThingManager.java:758)[106:org.eclipse.smarthome.core.thing:0.9.0.201610220816]
	at org.eclipse.smarthome.core.thing.internal.ThingManager$9$1.call(ThingManager.java:1)[106:org.eclipse.smarthome.core.thing:0.9.0.201610220816]
	at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:177)[99:org.eclipse.smarthome.core:0.9.0.201610220816]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_65]
	... 3 more
06:29:27.198 [DEBUG] [col.serial.MySensorsSerialConnection] - Final port list: /dev/pts/3
06:29:27.232 [DEBUG] [col.serial.MySensorsSerialConnection] - Successfully connected to serial port.
06:29:27.234 [DEBUG] [col.serial.MySensorsSerialConnection] - Waiting 3 seconds to allow correct reset trigger on serial connection opening
06:29:29.428 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
06:29:29.897 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
06:29:30.262 [DEBUG] [rs.internal.protocol.MySensorsReader] - ;255;3;0;14;Gateway startup complete.
06:29:30.274 [ERROR] [rs.internal.protocol.MySensorsReader] - (java.lang.NumberFormatException: For input string: "") on reading from serial port, message: class org.openhab.binding.mysensors.internal.protocol.serial.MySensorsSerialReader
06:29:30.283 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;0;0;18;2.0.1-beta

Things still seem to work, but do I have something wrong?

andreacioni

Hi @carlyler

what version of JVM are you using? 1.7 or 1.8?

carlyler

@andreacioni after reading this thread I realized you have done a lot of work here as well, thank you.

I am running:
pi@raspberrypi:~ $ java -version
java version "1.8.0_65"
Java(TM) SE Runtime Environment (build 1.8.0_65-b17)
Java HotSpot(TM) Client VM (build 25.65-b01, mixed mode)
pi@raspberrypi:~ $

hausinger

Hello community,

i have a small problem with openhab2 (on a orange pi with armbian - similar to raspberry) and mysensors Serial Gateway.
I installed openhab2 with the get methode and it works fine. I was able, to start it with openhab2.service (also automated) and openhab2 worked as it should. But if i want to connect the mysensors serial gateway to the orange pi with openhab2, openhab2 can't find my gateway. The log says "openhab is unable to connect to serial port, wrong serial port?"
But my serial port is ok.
If i stop openhab2.service and manual start openhab2, than all is fine, it can connect to serial gateway immediately and work fine. I don't know, why it can't work if openhab2 starts as service. Can you help me in this case?

Thank you.

And sorry for my english, it's not my first language

TimO

@hausinger Sounds like a problem with the permissions. The openhab2 service is running as user and group openhab and this user needs permission to the serial port (dialout).

sudo usermod -a -G dialout openhab

Denke

Hi all
I have a problem when my raspberry pi and mysensors/openhab when i do a restart. The problems seems to be ralated to the serial gateway and that the openhab dont find it or has the wrong settings.

Openhab starts when i make a reboot

I checked the serial by typing
stty -F /dev/ttyUSB0
response was

Seems here that the baudrate is wrong as my settings in the things file is

What i did to make it work was just to change this to use baud 9600 and then back to baud = 115200
after this it looked like

And everything started to work nicely

Does anyone now what the cause of this is and also how to fix it?

hausinger

@ TimO thank you. That was the problem

FutureCow

I have 2 simpel questions.

What is the status of the PR for mysensors to get inside openhab native?
What type of sensor do i need to use for a relay?

TimO

@FutureCow

Sadly there is no progress at all: https://github.com/openhab/openhab2-addons/pull/1243 Till now nobody found the time to look into the PR.
Use "Light" for a Relay. If you discover the device via PaperUI it will be represented as a "Light" (Switch).

blacey

@TimO I took a quick look at your pull request (personal curiosity) and noticed that one of your committed files includes a merge conflict - you probably want to fix that before the OpenHab team accepts your PR.

TimO

@blacey said:

I took a quick look at your pull request (personal curiosity) and noticed that one of your committed files includes a merge conflict

Hey @blacey, thank you for peeking in.
I haven't touched the PR for a long time, but it will be necessary soon because there were a lot changes in the development branch. I will fix that too!

blacey

@TimO Nice! While I have been a longtime Vera user, I think my next move will be OpenHab. I sponsored the Pine64 project on KickStarter and have one sitting on my project desk ready for some prototyping. I think it is great that you are making MySensors a first-class OpenHab 2.0 citizen. Hopefully Kai or one of the OpenHab contributors will merge your binding into the distro.

undee

@TimO It seems the binding does not support autoupdate="false" yet. Can you confirm this and do you consider adding this option? I could use the MQTT binding to get what I want (for example feedback of rollershutter position while moving based on the value sent by the sensor and not based on the command sent via the UI), but I don't want to move away from the MySensors binding.

ben999

Hi All

Big thumb up to all those who made it possible, awsome job here
Truely amazing for us diyers to have access to that technology so easily. Thanks a lot

BUT! I have a problem with binding... in short :
1- I installed openhab2 on RPi3 with a fresh SDCard
2-Updated java (as per https://community.openhab.org/t/my-openhab-connectio-failed/12957/11)
3- I followed tobof 's excellent step-by-step howto
4- I installed mysGateway (RPi acting as controller AND gateway)
5- With pi@raspberrypi:~/MySensors $ sudo ./examples_linux/mysGateway -d i can see that my motion sensor and my RPi gateway get on well

mysGateway: Starting gateway...
mysGateway: Protocol version - 2.0.1-beta
mysGateway: MCO:BGN:INIT GW,CP=RNNG---,VER=2.0.1-beta
mysGateway: TSF:LRT:OK
mysGateway: TSM:INIT
mysGateway: TSM:INIT:TSP OK
mysGateway: TSM:INIT:GW MODE
mysGateway: TSM:READY
mysGateway: MCO:REG:NOT NEEDED
mysGateway: MCO:BGN:STP
mysGateway: MCO:BGN:INIT OK,ID=0,PAR=0,DIS=0,REG=1
mysGateway: TSF:MSG:READ,1-1-0,s=1,c=1,t=16,pt=0,l=1,sg=0:1
mysGateway: TSF:MSG:READ,1-1-0,s=1,c=1,t=16,pt=0,l=1,sg=0:0
mysGateway: TSF:MSG:READ,1-1-0,s=1,c=1,t=16,pt=0,l=1,sg=0:1
mysGateway: TSF:MSG:READ,1-1-0,s=1,c=1,t=16,pt=0,l=1,sg=0:0

6- created a thing (text editor) for the bridge pi@raspberrypi:/usr/share/openhab2/conf/things $ nano home.things

Bridge mysensors:bridge-ser:gateway [ serialPort="/dev/pts/2", sendDelay=200 ] {  }

7- Following openhab2 "live" log with pi@raspberrypi:/usr/share/openhab2 $ sudo ./start_debug.sh

05:37:32.536 [DEBUG] [org.openhab.binding.mysensors       ] - BundleEvent STARTING - org.openhab.binding.mysensors                                                                                   
05:37:32.561 [DEBUG] [org.openhab.binding.mysensors       ] - BundleEvent STARTED - org.openhab.binding.mysensors                                                                                    
05:37:32.789 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.mysensors.internal.MySensorsHandlerFactory, component.id=0, service.id=110, service.bundleid=10, service.scope=bundle} - org.openhab.binding.mysensors                                                         
05:37:50.539 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.items'                                                                                                             
05:37:58.611 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.sitemap'                                                                                                           
05:37:59.319 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.things'                                                                                                            
05:37:59.664 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'mysensors:bridge-ser:gateway' has been added.                                                                                   
05:38:00.412 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=232, service.bundleid=10, service.scope=singleton} - org.openhab.binding.mysensors                                                                                                                                                          
05:38:00.435 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=mysensors:bridge-ser, thing.id=mysensors:bridge-ser:gateway, service.id=233, service.bundleid=10, service.scope=singleton} - org.openhab.binding.mysensors                                                                                    
05:38:00.473 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:gateway' changed from UNINITIALIZED to INITIALIZING                                                              
05:38:00.474 [DEBUG] [nsors.handler.MySensorsBridgeHandler] - Initialization of the MySensors Bridge                                                                                                 
05:38:00.594 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'MotionTest-mysensors:motion:1584d6773a3:armed' has been added.
05:38:00.605 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'MotionTest-mysensors:motion:1584d6773a3:tripped' has been added.
RXTX Warning:  Removing stale lock file. /var/lock/LCK..ttyAMA0
05:38:00.658 [DEBUG] [col.serial.MySensorsSerialConnection] - Successfully connected to serial port.
05:38:00.677 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:gateway' changed from INITIALIZING to ONLINE
05:38:05.333 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
05:38:06.180 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
05:38:08.009 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
05:38:08.223 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
05:38:08.951 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
05:38:09.203 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
05:38:11.343 [INFO ] [o.myopenhab.internal.MyOpenHABClient] - Connected to my.openHAB service (UUID = 7c0faa03-e826-473a-b1f7-8b685b487bb8, base URL = http://localhost:8080)

Looks pretty to me...
8- but then i try to register my sensor (arduino pro and 501PIR sensor) with paper UI
No luck. Discovery window stays on forever!
0_1479359161452_Scan.jpeg

sudo usermod -a -G dialout openhab returns "unknown user" ...

Any clue ?
Thanks a lot for your help !

ben999

Binding is still unsuccessful

Following error disapeared (Updated my previous post).
Guess that happened as RPi started reboot before openhab session was properly closed... 3 reboots cured that error...

in pi@raspberrypi:/usr/share/openhab2/userdata/logs $ nano openhab.log :

2016-11-17 06:40:00.094 [DEBUG] [org.openhab.binding.mysensors       ] - BundleEvent STARTING - org.openhab.binding.mysensors
2016-11-17 06:40:00.383 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.bindin$
2016-11-17 06:40:00.480 [DEBUG] [org.openhab.binding.mysensors       ] - BundleEvent STARTED - org.openhab.binding.mysensors
2016-11-17 06:40:11.249 [WARN ] [eclipse.jetty.servlet.ServletHandler] -
javax.servlet.ServletException: A MultiException has 1 exceptions.  They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_0,0,33431755) has been shut down

        at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:489)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76)[12:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812)[82:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)[82:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:70)[173:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)[80:org.eclipse.jetty.security:9.2.14.v20151106]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:271)[173:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)[82:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80)[173:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.Server.handle(Server.java:499)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)[73:org.eclipse.jetty.io:9.2.14.v20151106]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)[84:org.eclipse.jetty.util:9.2.14.v20151106]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)[84:org.eclipse.jetty.util:9.2.14.v20151106]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
Caused by: A MultiException has 1 exceptions.  They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_0,0,33431755) has been shut down

        at org.jvnet.hk2.internal.FactoryCreator.getFactoryHandle(FactoryCreator.java:106)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.FactoryCreator.dispose(FactoryCreator.java:173)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.SystemDescriptor.dispose(SystemDescriptor.java:526)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.glassfish.jersey.process.internal.RequestScope$Instance.remove(RequestScope.java:532)[158:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.process.internal.RequestScope$Instance.release(RequestScope.java:549)[158:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:319)[158:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)[159:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)[159:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        ... 26 more
Caused by: java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_0,0,33431755) has been shut down
        at org.jvnet.hk2.internal.ServiceLocatorImpl.checkState(ServiceLocatorImpl.java:2288)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandleImpl(ServiceLocatorImpl.java:629)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:622)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:640)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.FactoryCreator.getFactoryHandle(FactoryCreator.java:103)[151:org.glassfish.hk2.locator:2.4.0.b34]
        ... 34 more
2016-11-17 06:40:11.296 [WARN ] [org.eclipse.jetty.server.HttpChannel] - /rest/events
javax.servlet.ServletException: javax.servlet.ServletException: A MultiException has 1 exceptions.  They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_0,0,33431755) has been shut down

        at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:88)[173:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.Server.handle(Server.java:499)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)[73:org.eclipse.jetty.io:9.2.14.v20151106]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)[84:org.eclipse.jetty.util:9.2.14.v20151106]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)[84:org.eclipse.jetty.util:9.2.14.v20151106]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
Caused by: javax.servlet.ServletException: A MultiException has 1 exceptions.  They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_0,0,33431755) has been shut down

        at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:489)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76)[12:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812)[82:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)[82:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:70)[173:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)[80:org.eclipse.jetty.security:9.2.14.v20151106]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:271)[173:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)[82:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)[81:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80)[173:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        ... 8 more
Caused by: A MultiException has 1 exceptions.  They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_0,0,33431755) has been shut down

        at org.jvnet.hk2.internal.FactoryCreator.getFactoryHandle(FactoryCreator.java:106)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.FactoryCreator.dispose(FactoryCreator.java:173)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.SystemDescriptor.dispose(SystemDescriptor.java:526)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.glassfish.jersey.process.internal.RequestScope$Instance.remove(RequestScope.java:532)[158:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.process.internal.RequestScope$Instance.release(RequestScope.java:549)[158:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:319)[158:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:319)[158:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)[159:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)[159:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473)[156:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        ... 26 more
Caused by: java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_0,0,33431755) has been shut down
        at org.jvnet.hk2.internal.ServiceLocatorImpl.checkState(ServiceLocatorImpl.java:2288)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandleImpl(ServiceLocatorImpl.java:629)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:622)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:640)[151:org.glassfish.hk2.locator:2.4.0.b34]
        at org.jvnet.hk2.internal.FactoryCreator.getFactoryHandle(FactoryCreator.java:103)[151:org.glassfish.hk2.locator:2.4.0.b34]
        ... 34 more
2016-11-17 06:40:11.330 [WARN ] [org.eclipse.jetty.server.HttpChannel] - Could not send response error 500: javax.servlet.ServletException: javax.servlet.ServletException: A MultiException has 1 e$
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_0,0,33431755) has been shut down

2016-11-17 06:40:20.925 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.items'
2016-11-17 06:40:28.127 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.sitemap'
2016-11-17 06:40:29.101 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.things'
2016-11-17 06:40:30.364 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=235, service.bundleid=10, s$
2016-11-17 06:40:30.385 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=mysensors:bridge-ser, thing.i$
2016-11-17 06:40:30.435 [DEBUG] [nsors.handler.MySensorsBridgeHandler] - Initialization of the MySensors Bridge
2016-11-17 06:40:30.654 [DEBUG] [col.serial.MySensorsSerialConnection] - Successfully connected to serial port.
2016-11-17 06:40:36.145 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-11-17 06:40:38.163 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-11-17 06:40:38.712 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-11-17 06:40:39.160 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2016-11-17 06:40:39.955 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2016-11-17 06:40:40.396 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2016-11-17 06:40:42.527 [INFO ] [o.myopenhab.internal.MyOpenHABClient] - Connected to my.openHAB service (UUID = 7c0faa03-e826-473a-b1f7-8b685b487bb8, base URL = http://localhost:8080)

TimO

@ben999 The error in your second post does not seem to be related the to binding and I've no clue what it means. So I'm glad the error is gone.

Have you enabled DEBUG for the binding? Please show me the output after you started the discovery process. The connection to the serial gateway is successful, so no need to change the permissions with usermod at the moment.

With debug enabled you should see the messages incoming from the gateway. If you don't see the messages arriving please check the connection between serial gateway and the node.

ben999

@TimO Thanks a lot for your message
Talking right to the boss !!

Actually, except that https://forum.mysensors.org/uploads/files/1479359162183-scan.jpeg nothing else happens...

Log from sensor (arduino micro++nrf24+dth22) :
No change, even when i launch a "scan for things"

Starting sensor (RNNNA-, 2.0.0)
TSM:INIT
TSM:RADIO:OK
TSP:ASSIGNID:OK (ID=1)
TSM:FPAR
TSP:MSG:SEND 1-1-255-255 s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=bc:
TSP:MSG:READ 0-0-1 s=255,c=3,t=8,pt=1,l=1,sg=0:0
TSP:MSG:FPAR RES (ID=0, dist=0)
TSP:MSG:PAR OK (ID=0, dist=1)
TSM:FPAR:OK
TSM:ID
TSM:CHKID:OK (ID=1)
TSM:UPL
TSP:PING:SEND (dest=0)
TSP:MSG:SEND 1-1-0-0 s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=ok:1
TSP:MSG:READ 0-0-1 s=255,c=3,t=25,pt=1,l=1,sg=0:1
TSP:MSG:PONG RECV (hops=1)
TSP:CHKUPL:OK
TSM:UPL:OK
TSM:READY
TSP:MSG:SEND 1-1-0-0 s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=ok:0100
!TSP:MSG:SEND 1-1-0-0 s=255,c=0,t=17,pt=0,l=5,sg=0,ft=0,st=fail:2.0.0
TSP:MSG:SEND 1-1-0-0 s=255,c=3,t=6,pt=1,l=1,sg=0,ft=1,st=ok:0
TSP:MSG:SEND 1-1-0-0 s=255,c=3,t=11,pt=0,l=22,sg=0,ft=0,st=ok:TemperatureAndHumidity
TSP:MSG:SEND 1-1-0-0 s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=ok:1.1
TSP:MSG:SEND 1-1-0-0 s=0,c=0,t=7,pt=0,l=0,sg=0,ft=0,st=ok:
TSP:MSG:SEND 1-1-0-0 s=1,c=0,t=6,pt=0,l=0,sg=0,ft=0,st=ok:
Request registration...
TSP:MSG:SEND 1-1-0-0 s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=ok:2
TSP:MSG:READ 0-0-1 s=255,c=3,t=27,pt=1,l=1,sg=0:1
Node registration=1
Init complete, id=1, parent=0, distance=1, registration=1
TSP:MSG:SEND 1-1-0-0 s=1,c=1,t=0,pt=7,l=5,sg=0,ft=0,st=ok:18.5
T: 18.50
TSP:MSG:SEND 1-1-0-0 s=0,c=1,t=1,pt=7,l=5,sg=0,ft=0,st=ok:68.1
H: 68.10

And that's the openhab log... again, no change when i start a "scan for things"... :

pi@raspberrypi:/usr/share/openhab2 $ sudo ./start_debug.sh 
Launching the openHAB runtime...
Listening for transport dt_socket at address: 5005

                          __  _____    ____      
  ____  ____  ___  ____  / / / /   |  / __ )     
 / __ \/ __ \/ _ \/ __ \/ /_/ / /| | / __  | 
/ /_/ / /_/ /  __/ / / / __  / ___ |/ /_/ /      
\____/ .___/\___/_/ /_/_/ /_/_/  |_/_____/     
    /_/                        2.0.0-SNAPSHOT
                               Build #574   

Hit '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
Hit '<ctrl-d>' or type 'system:shutdown' or 'logout' to shutdown openHAB.

openhab> log:set DEBUG org.openhab.binding.mysensors
openhab> log:tail
19:47:20.265 [DEBUG] [org.openhab.binding.mysensors       ] - BundleEvent STARTING - org.openhab.binding.mysensors
19:47:20.517 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.mysensors.internal.MySensorsHandlerFactory, component.id=0, service.id=109, service.bundleid=10, service.scope=bundle} - org.openhab.binding.mysensors
19:47:20.619 [DEBUG] [org.openhab.binding.mysensors       ] - BundleEvent STARTED - org.openhab.binding.mysensors
19:47:40.172 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.items'
19:47:48.877 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.sitemap'
19:47:49.580 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.things'
19:47:49.939 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'mysensors:bridge-ser:gateway' has been added.
19:47:50.853 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=234, service.bundleid=10, service.scope=singleton} - org.openhab.binding.mysensors
19:47:50.869 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=mysensors:bridge-ser, thing.id=mysensors:bridge-ser:gateway, service.id=235, service.bundleid=10, service.scope=singleton} - org.openhab.binding.mysensors                                                                                    
19:47:50.908 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:gateway' changed from UNINITIALIZED to INITIALIZING                                                              
19:47:50.915 [DEBUG] [nsors.handler.MySensorsBridgeHandler] - Initialization of the MySensors Bridge                                                                                                 
19:47:51.047 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'mysensors:humidity:4008f727' has been added.                                                                                    
19:47:51.072 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:4008f727' changed from UNINITIALIZED to INITIALIZING                                                               
19:47:51.073 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=mysensors:humidity, thing.id=mysensors:humidity:4008f727, service.id=237, service.bundleid=10, service.scope=singleton} - org.openhab.binding.mysensors                                                                                       
19:47:51.084 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'mysensors:temperature:762194fe' has been added.                                                                                 
19:47:51.210 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=mysensors:temperature, thing.id=mysensors:temperature:762194fe, service.id=238, service.bundleid=10, service.scope=singleton} - org.openhab.binding.mysensors                                                                                 
19:47:51.212 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:762194fe' changed from UNINITIALIZED to INITIALIZING                                                            
19:47:51.329 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:4008f727' changed from INITIALIZING to ONLINE                                                                      
19:47:51.330 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:762194fe' changed from INITIALIZING to ONLINE                                                                   
19:47:51.332 [DEBUG] [col.serial.MySensorsSerialConnection] - Successfully connected to serial port.                                                                                                 
19:47:51.341 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'MotionTest-mysensors:motion:1584d6773a3:armed' has been added.                                                                   
19:47:51.345 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'MotionTest-mysensors:motion:1584d6773a3:tripped' has been added.                                                                 
19:47:51.357 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:gateway' changed from INITIALIZING to ONLINE                                                                     
19:47:51.413 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'mysensors_humidity_4008f727_battery' has been added.                                                                             
19:47:51.417 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'mysensors_humidity_4008f727_battery-mysensors:humidity:4008f727:battery' has been added.                                         
19:47:51.421 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'mysensors_humidity_4008f727_hum' has been added.                                                                                 
19:47:51.425 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'mysensors_humidity_4008f727_hum-mysensors:humidity:4008f727:hum' has been added.                                                 
19:47:51.431 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'mysensors_temperature_762194fe_battery' has been added.                                                                          
19:47:51.434 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'mysensors_temperature_762194fe_battery-mysensors:temperature:762194fe:battery' has been added.
19:47:51.440 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'mysensors_temperature_762194fe_temp' has been added.
19:47:51.454 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'mysensors_temperature_762194fe_temp-mysensors:temperature:762194fe:temp' has been added.
19:47:56.749 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
19:47:57.810 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
19:47:58.557 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
19:47:59.161 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
19:47:59.682 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
19:47:59.807 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
19:48:04.034 [INFO ] [o.myopenhab.internal.MyOpenHABClient] - Connected to my.openHAB service (UUID = 7c0faa03-e826-473a-b1f7-8b685b487bb8, base URL = http://localhost:8080)

Is there any other log that is worth having a look at ?
This is really strange, because when i hook up a PIR sensor to the same arduino and nrf24, and i launch pi@raspberrypi:~/MySensors $ sudo ./examples_linux/mysGateway -d i can see that arduino and raspberry interract together...

Thanks a lot for your time

TimO

@ben999 The OH2 log looks good, but could you please enable debug output in OH2 for the binding as described in the Wiki?

In the log from the node I see that the presentation message is the one that failed to deliver. Does this happen all the time? The binding is looking for that message. This could be a power issue.

ben999

@TimO thank you for your answer
Both RPi and sensors have been power with different power supplies but no change
Then, to get the debug output at the karaf prompt I typed : openhab> log:set DEBUG
This is what i got when asking for a "search for things" process:

openhab> log:set DEBUG
openhab> log:tail
22:59:40.423 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Command: 'log:clear' returned 'null'
22:59:42.378 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
22:59:43.026 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Executing command: 'log:set DEBUG'
22:59:43.028 [DEBUG] [org.apache.felix.configadmin        ] - getProperties()
22:59:43.032 [DEBUG] [org.apache.felix.configadmin        ] - getProperties()
22:59:44.731 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Executing command: 'log:tail'
22:59:46.716 [DEBUG] [io.socket.engineio.client.Socket    ] - writing ping packet - expecting pong within 60000ms
22:59:46.720 [DEBUG] [io.socket.engineio.client.Socket    ] - flushing 1 packets in socket
22:59:46.765 [DEBUG] [io.socket.engineio.client.Socket    ] - socket received: type 'pong', data 'null'
22:59:55.667 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@10fcc9b{/192.168.1.9:45209<->8080,Open,in,out,-,-,30000/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
22:59:55.669 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@10fcc9b{/192.168.1.9:45209<->8080,Open,in,out,-,-,30002/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout expired
22:59:55.671 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SelectChannelEndPoint@10fcc9b{/192.168.1.9:45209<->8080,Open,in,out,-,-,30004/30000,HttpConnection}{io=0,kio=0,kro=1}
22:59:57.110 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@13e699a
22:59:57.112 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@13e699a
22:59:57.113 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - onOpen SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,0/30000,null}{io=0,kio=0,kro=0}
22:59:57.116 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,1/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 1 ms, remaining: 29999 ms
22:59:57.123 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - new HttpChannelOverHttp@1a5f1b6{r=0,c=false,a=IDLE,uri=} -> SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,9/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@1d0ab0c{s=IDLE i=true a=null}
22:59:57.126 [DEBUG] [.eclipse.jetty.server.HttpConnection] - New HTTP Connection HttpConnection@ec8647[IDLE,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->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@1a5f1b6{r=0,c=false,a=IDLE,uri=}]
22:59:57.128 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - onOpen HttpConnection@ec8647[IDLE,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->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@1a5f1b6{r=0,c=false,a=IDLE,uri=}]
22:59:57.133 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested HttpConnection@ec8647[IDLE,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->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@1a5f1b6{r=0,c=false,a=IDLE,uri=}]
22:59:57.136 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - IDLE-->FILL_INTERESTED HttpConnection@ec8647[FILL_INTERESTED,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->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@1a5f1b6{r=0,c=false,a=IDLE,uri=}]
22:59:57.138 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 0 -> 1 for SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}
22:59:57.139 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@b87e8a
22:59:57.141 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Created SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,R,-,3/30000,HttpConnection}{io=1,kio=0,kro=0}
22:59:57.143 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@b87e8a
22:59:57.145 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 0 -> 1 on SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,R,-,7/30000,HttpConnection}{io=1,kio=1,kro=0}
22:59:57.146 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
22:59:57.148 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 1/1 selected
22:59:57.150 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 1 -> 0 on SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,R,-,12/30000,HttpConnection}{io=1,kio=0,kro=1}
22:59:57.152 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 1 -> 0 for SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,R,-,14/30000,HttpConnection}{io=0,kio=0,kro=1}
22:59:57.153 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@b87e8a
22:59:57.156 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILL_INTERESTED-->FILLING HttpConnection@ec8647[FILLING,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,17/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@1a5f1b6{r=0,c=false,a=IDLE,uri=}]
22:59:57.157 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@b87e8a
22:59:57.158 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
22:59:57.158 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@ec8647[FILLING,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,20/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of 0},g=HttpGenerator{s=START},c=HttpChannelOverHttp@1a5f1b6{r=0,c=false,a=IDLE,uri=}] onFillable HttpChannelState@1d0ab0c{s=IDLE i=true a=null}
22:59:57.159 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 381 SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,22/30000,HttpConnection}{io=0,kio=0,kro=1}
22:59:57.160 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@16d7302[p=0,l=381,c=8192,r=381]={<<<GET /rest/discove....6,en;q=0.4\r\n\r\n>>>2.168.1.96:8080/u...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
22:59:57.161 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> SPACE1
22:59:57.162 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE1 --> URI
22:59:57.162 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - URI --> SPACE2
22:59:57.163 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE2 --> REQUEST_VERSION
22:59:57.163 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - REQUEST_VERSION --> HEADER
22:59:57.164 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_VALUE
22:59:57.165 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
22:59:57.167 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:59:57.172 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:59:57.173 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:59:57.175 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_VALUE
22:59:57.177 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
22:59:57.178 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:59:57.180 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_VALUE
22:59:57.181 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
22:59:57.183 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:59:57.184 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_VALUE
22:59:57.185 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
22:59:57.187 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:59:57.188 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:59:57.189 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:59:57.190 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_VALUE
22:59:57.192 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
22:59:57.193 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:59:57.194 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> END
22:59:57.195 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@1a5f1b6{r=1,c=false,a=IDLE,uri=/rest/discovery} messageComplete
22:59:57.201 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@1a10417 EOF
22:59:57.204 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@1a5f1b6{r=1,c=false,a=IDLE,uri=/rest/discovery} handle enter
22:59:57.207 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@1d0ab0c{s=IDLE i=true a=null} handling IDLE
22:59:57.214 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@1a5f1b6{r=1,c=false,a=DISPATCHED,uri=/rest/discovery} action REQUEST_DISPATCH
22:59:57.218 [DEBUG] [org.eclipse.jetty.server.Server     ] - REQUEST GET /rest/discovery on HttpChannelOverHttp@1a5f1b6{r=1,c=false,a=DISPATCHED,uri=/rest/discovery}
22:59:57.220 [DEBUG] [ax.web.service.spi.model.ServerModel] - Matching [/rest/discovery]...
22:59:57.223 [DEBUG] [ax.web.service.spi.model.ServerModel] - Path [/rest/discovery] matched to {pattern=/rest/.*,model=ServletModel{id=org.ops4j.pax.web.service.spi.model.ServletModel-2,name=org.ops4j.pax.web.service.spi.model.ServletModel-2,urlPatterns=[/rest/*],alias=/rest,servlet=com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge@bc5ed1,initParams={},context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-1,name=,httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default],contextParams={},virtualHosts={},connectors={}}}}
22:59:57.225 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]}
22:59:57.227 [DEBUG] [.jetty.server.handler.ContextHandler] - context=||/rest/discovery @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]}
22:59:57.228 [DEBUG] [org.eclipse.jetty.server.session    ] - sessionManager=org.ops4j.pax.web.service.jetty.internal.LateInvalidatingHashSessionManager@32d70e
22:59:57.229 [DEBUG] [org.eclipse.jetty.server.session    ] - session=null
22:59:57.231 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - servlet |/rest|/discovery -> org.ops4j.pax.web.service.spi.model.ServletModel-2@378be0fa==com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge,-1,true
22:59:57.232 [DEBUG] [ce.jetty.internal.HttpServiceContext] - Handling request for [/rest/discovery] using http context [DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]]
22:59:57.233 [DEBUG] [y.internal.HttpServiceServletHandler] - handling request org.ops4j.pax.web.service.jetty.internal.HttpServiceRequestWrapper@166f693, org.ops4j.pax.web.service.jetty.internal.HttpServiceResponseWrapper@1596f67
22:59:57.235 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - chain=null
22:59:57.244 [DEBUG] [e.internal.WriterInterceptorExecutor] - Message body writer (class com.eclipsesource.jaxrs.provider.gson.GsonProvider) is trying to close the entity output stream. Not closing.
22:59:57.246 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@5bfca8[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,13,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1b5d408] generate: NEED_HEADER (null,[p=0,l=13,c=8192,r=13],true)@START
22:59:57.249 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@5bfca8[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,13,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1b5d408] generate: FLUSH ([p=0,l=141,c=8192,r=141],[p=0,l=13,c=8192,r=13],true)@COMPLETING
22:59:57.253 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 154 SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,W,93/30000,HttpConnection}{io=0,kio=0,kro=1}
22:59:57.256 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@5bfca8[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,13,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1b5d408] generate: DONE ([p=141,l=141,c=8192,r=0],[p=13,l=13,c=8192,r=0],true)@END
22:59:57.259 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ o.e.j.s.h.ContextHandler@190a83a{/static,null,AVAILABLE}
22:59:57.261 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.201611041332 [100], contextID=default]}
22:59:57.262 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.201611041332 [137], contextID=default]}
22:59:57.264 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.201611041332 [138], contextID=default]}
22:59:57.269 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@1ea92c5}
22:59:57.270 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.201611041332 [186], contextID=default]}
22:59:57.272 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.classic_0.9.0.201611041332 [187], contextID=default]}
22:59:57.273 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.201611041332 [188], contextID=default]}
22:59:57.274 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.io.rest.docs_2.0.0.201611062131 [189], contextID=default]}
22:59:57.276 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.0.0.201611062131 [192], contextID=default]}
22:59:57.277 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.0.0.201611062131 [168], contextID=default]}
22:59:57.278 [DEBUG] [org.eclipse.jetty.server.Server     ] - RESPONSE /rest/discovery  200 handled=true
22:59:57.279 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@1d0ab0c{s=DISPATCHED i=true a=null} unhandle DISPATCHED
22:59:57.281 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - reset HttpParser{s=END,0 of 0}
22:59:57.281 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - END --> START
22:59:57.283 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@1a5f1b6{r=1,c=false,a=IDLE,uri=} handle exit, result COMPLETE
22:59:57.301 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,45/30000,HttpConnection}{io=0,kio=0,kro=1}
22:59:57.303 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,46/30000,HttpConnection}{io=0,kio=0,kro=1}
22:59:57.304 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@1860225[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
22:59:57.307 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested HttpConnection@ec8647[FILLING,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,50/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@1a5f1b6{r=1,c=false,a=IDLE,uri=}]
22:59:57.310 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING-->FILLING_FILL_INTERESTED HttpConnection@ec8647[FILLING_FILL_INTERESTED,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,52/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@1a5f1b6{r=1,c=false,a=IDLE,uri=}]
22:59:57.313 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING_FILL_INTERESTED-->FILL_INTERESTED HttpConnection@ec8647[FILL_INTERESTED,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,55/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@1a5f1b6{r=1,c=false,a=IDLE,uri=}]
22:59:57.315 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 0 -> 1 for SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=1}
22:59:57.316 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@b87e8a
22:59:57.318 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 0/1 selected
22:59:57.320 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@b87e8a
22:59:57.322 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 0 -> 1 on SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,R,-,7/30000,HttpConnection}{io=1,kio=1,kro=1}
22:59:57.323 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
23:00:01.810 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 1/1 selected
23:00:01.812 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 1 -> 0 on SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,R,-,4497/30000,HttpConnection}{io=1,kio=0,kro=1}
23:00:01.814 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 1 -> 0 for SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,R,-,4499/30000,HttpConnection}{io=0,kio=0,kro=1}
23:00:01.814 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@b87e8a
23:00:01.816 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILL_INTERESTED-->FILLING HttpConnection@ec8647[FILLING,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,4502/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@1a5f1b6{r=1,c=false,a=IDLE,uri=}]
23:00:01.817 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@b87e8a
23:00:01.818 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
23:00:01.819 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@ec8647[FILLING,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,4504/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@1a5f1b6{r=1,c=false,a=IDLE,uri=}] onFillable HttpChannelState@1d0ab0c{s=IDLE i=true a=null}
23:00:01.821 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 525 SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,4506/30000,HttpConnection}{io=0,kio=0,kro=1}
23:00:01.822 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@16d7302[p=0,l=525,c=8192,r=525]={<<<POST /rest/discov...d":"mysensors"}>>>\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\x00\x00}
23:00:01.822 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> SPACE1
23:00:01.823 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE1 --> URI
23:00:01.824 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - URI --> SPACE2
23:00:01.824 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE2 --> REQUEST_VERSION
23:00:01.825 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - REQUEST_VERSION --> HEADER
23:00:01.826 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
23:00:01.827 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
23:00:01.828 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
23:00:01.828 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
23:00:01.829 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_VALUE
23:00:01.830 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
23:00:01.831 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
23:00:01.832 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
23:00:01.832 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
23:00:01.833 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
23:00:01.834 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
23:00:01.835 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
23:00:01.835 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
23:00:01.836 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
23:00:01.837 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
23:00:01.838 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
23:00:01.839 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
23:00:01.839 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_VALUE
23:00:01.840 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
23:00:01.841 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
23:00:01.842 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
23:00:01.843 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER

Puneit Thukral

This post is deleted!

ben999

end of debug log (sorry, post too long)

23:00:01.843 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
23:00:01.844 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
23:00:01.845 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> CONTENT
23:00:01.846 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@1a5f1b6{r=2,c=false,a=IDLE,uri=/rest/discovery/bindings/mysensors/scan} handle enter
23:00:01.847 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@1d0ab0c{s=IDLE i=true a=null} handling IDLE
23:00:01.848 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@1a5f1b6{r=2,c=false,a=DISPATCHED,uri=/rest/discovery/bindings/mysensors/scan} action REQUEST_DISPATCH
23:00:01.849 [DEBUG] [org.eclipse.jetty.server.Server     ] - REQUEST POST /rest/discovery/bindings/mysensors/scan on HttpChannelOverHttp@1a5f1b6{r=2,c=false,a=DISPATCHED,uri=/rest/discovery/bindings/mysensors/scan}
23:00:01.850 [DEBUG] [ax.web.service.spi.model.ServerModel] - Matching [/rest/discovery/bindings/mysensors/scan]...
23:00:01.851 [DEBUG] [ax.web.service.spi.model.ServerModel] - Path [/rest/discovery/bindings/mysensors/scan] matched to {pattern=/rest/.*,model=ServletModel{id=org.ops4j.pax.web.service.spi.model.ServletModel-2,name=org.ops4j.pax.web.service.spi.model.ServletModel-2,urlPatterns=[/rest/*],alias=/rest,servlet=com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge@bc5ed1,initParams={},context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-1,name=,httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default],contextParams={},virtualHosts={},connectors={}}}}
23:00:01.852 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]}
23:00:01.853 [DEBUG] [.jetty.server.handler.ContextHandler] - context=||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]}
23:00:01.853 [DEBUG] [org.eclipse.jetty.server.session    ] - sessionManager=org.ops4j.pax.web.service.jetty.internal.LateInvalidatingHashSessionManager@32d70e
23:00:01.854 [DEBUG] [org.eclipse.jetty.server.session    ] - session=null
23:00:01.855 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - servlet |/rest|/discovery/bindings/mysensors/scan -> org.ops4j.pax.web.service.spi.model.ServletModel-2@378be0fa==com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge,-1,true
23:00:01.856 [DEBUG] [ce.jetty.internal.HttpServiceContext] - Handling request for [/rest/discovery/bindings/mysensors/scan] using http context [DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]]
23:00:01.857 [DEBUG] [y.internal.HttpServiceServletHandler] - handling request org.ops4j.pax.web.service.jetty.internal.HttpServiceRequestWrapper@a929e4, org.ops4j.pax.web.service.jetty.internal.HttpServiceResponseWrapper@13d3535
23:00:01.857 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - chain=null
23:00:01.872 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@5bfca8[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,4,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1866dfa] generate: NEED_HEADER (null,[p=0,l=4,c=8192,r=4],true)@START
23:00:01.874 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@5bfca8[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,4,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1866dfa] generate: FLUSH ([p=0,l=134,c=8192,r=134],[p=0,l=4,c=8192,r=4],true)@COMPLETING
23:00:01.875 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 138 SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,W,54/30000,HttpConnection}{io=0,kio=0,kro=1}
23:00:01.877 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@5bfca8[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,4,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1866dfa] generate: DONE ([p=134,l=134,c=8192,r=0],[p=4,l=4,c=8192,r=0],true)@END
23:00:01.879 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ o.e.j.s.h.ContextHandler@190a83a{/static,null,AVAILABLE}
23:00:01.880 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.201611041332 [100], contextID=default]}
23:00:01.881 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.201611041332 [137], contextID=default]}
23:00:01.882 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.201611041332 [138], contextID=default]}
23:00:01.883 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@1ea92c5}
23:00:01.884 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.201611041332 [186], contextID=default]}
23:00:01.884 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.classic_0.9.0.201611041332 [187], contextID=default]}
23:00:01.885 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.201611041332 [188], contextID=default]}
23:00:01.886 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.io.rest.docs_2.0.0.201611062131 [189], contextID=default]}
23:00:01.887 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.0.0.201611062131 [192], contextID=default]}
23:00:01.888 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/discovery/bindings/mysensors/scan @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.0.0.201611062131 [168], contextID=default]}
23:00:01.889 [DEBUG] [org.eclipse.jetty.server.Server     ] - RESPONSE /rest/discovery/bindings/mysensors/scan  200 handled=true
23:00:01.891 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@1d0ab0c{s=DISPATCHED i=true a=null} unhandle DISPATCHED
23:00:01.893 [DEBUG] [.eclipse.jetty.server.HttpConnection] - unconsumed input HttpConnection@ec8647[FILLING,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,16/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=CONTENT,0 of 25},g=HttpGenerator{s=END},c=HttpChannelOverHttp@1a5f1b6{r=2,c=true,a=COMPLETED,uri=/rest/discovery/bindings/mysensors/scan}]
23:00:01.894 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=CONTENT HeapByteBuffer@16d7302[p=500,l=525,c=8192,r=25]={POST /rest/discov....6,en;q=0.4\r\n\r\n<<<{"bindingId":"mysensors"}>>>\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\x00\x00}
23:00:01.895 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@1a5f1b6{r=2,c=true,a=COMPLETED,uri=/rest/discovery/bindings/mysensors/scan} content java.nio.HeapByteBufferR[pos=500 lim=525 cap=8192]
23:00:01.897 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=CONTENT HeapByteBuffer@16d7302[p=525,l=525,c=8192,r=0]={POST /rest/discov...d":"mysensors"}<<<>>>\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\x00\x00}
23:00:01.897 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - CONTENT --> END
23:00:01.898 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@1a5f1b6{r=2,c=true,a=COMPLETED,uri=/rest/discovery/bindings/mysensors/scan} messageComplete
23:00:01.899 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@1a10417 EOF
23:00:01.901 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,24/30000,HttpConnection}{io=0,kio=0,kro=1}
23:00:01.903 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@ec8647[FILLING,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,26/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,25 of 25},g=HttpGenerator{s=END},c=HttpChannelOverHttp@1a5f1b6{r=2,c=true,a=COMPLETED,uri=/rest/discovery/bindings/mysensors/scan}] filled 0
23:00:01.904 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@1a10417 eof EOF
23:00:01.905 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - reset HttpParser{s=END,25 of 25}
23:00:01.905 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - END --> START
23:00:01.907 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@1a5f1b6{r=2,c=false,a=IDLE,uri=} handle exit, result COMPLETE
23:00:01.908 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,31/30000,HttpConnection}{io=0,kio=0,kro=1}
23:00:01.909 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,33/30000,HttpConnection}{io=0,kio=0,kro=1}
23:00:01.910 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@1860225[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
23:00:01.912 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested HttpConnection@ec8647[FILLING,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,36/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@1a5f1b6{r=2,c=false,a=IDLE,uri=}]
23:00:01.914 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING-->FILLING_FILL_INTERESTED HttpConnection@ec8647[FILLING_FILL_INTERESTED,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,38/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@1a5f1b6{r=2,c=false,a=IDLE,uri=}]
23:00:01.917 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING_FILL_INTERESTED-->FILL_INTERESTED HttpConnection@ec8647[FILL_INTERESTED,SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,-,-,40/30000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@1a5f1b6{r=2,c=false,a=IDLE,uri=}]
23:00:01.918 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 0 -> 1 for SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=1}
23:00:01.919 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@b87e8a
23:00:01.920 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 0/1 selected
23:00:01.923 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@b87e8a
23:00:01.925 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 0 -> 1 on SelectChannelEndPoint@15c7d05{/192.168.1.9:45427<->8080,Open,in,out,R,-,7/30000,HttpConnection}{io=1,kio=1,kro=1}
23:00:01.926 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
23:00:09.067 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
23:00:11.859 [DEBUG] [io.socket.engineio.client.Socket    ] - writing ping packet - expecting pong within 60000ms
23:00:11.859 [DEBUG] [io.socket.engineio.client.Socket    ] - flushing 1 packets in socket
23:00:11.904 [DEBUG] [io.socket.engineio.client.Socket    ] - socket received: type 'pong', data 'null'

192.168.1.9 is the computer (ubuntu) from which i do ssh...

And this is the log during "idle"

23:02:48.131 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
23:02:55.692 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@10fcc9b{/192.168.1.9:45209<->8080,Open,in,out,-,-,30000/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
23:02:55.693 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@10fcc9b{/192.168.1.9:45209<->8080,Open,in,out,-,-,30002/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout expired
23:02:55.695 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SelectChannelEndPoint@10fcc9b{/192.168.1.9:45209<->8080,Open,in,out,-,-,30003/30000,HttpConnection}{io=0,kio=0,kro=1}
23:03:08.614 [DEBUG] [io.socket.engineio.client.Socket    ] - writing ping packet - expecting pong within 60000ms
23:03:08.614 [DEBUG] [io.socket.engineio.client.Socket    ] - flushing 1 packets in socket
23:03:08.655 [DEBUG] [io.socket.engineio.client.Socket    ] - socket received: type 'pong', data 'null'

TimO

@ben999 My bad sorry, your first log already contained the debug information.

To which serial port is the gateway connected? I see that it connected, but I'm missing a few messages that should appear. Could you please specify the bridge / gateway (only the gateway) in the *.things file according to the description in the wiki and see if that works?

We should see the messages the gateway receives in the debug output.

FutureCow

I have almost the same problem. Items don't get added to the inbox when a new node is found.
Also when i add them manualy, things don't work(it was working earlier) So i think something changed for the bindings. So at the moment the MySensors binding is not working with latest snapshot(#597)

My Debug log:

2016-11-20 01:43:15.119 [DEBUG] [ernal.handler.MySensorsBridgeHandler] - Initialization of the MySensors bridge
2016-11-20 01:43:15.119 [DEBUG] [col.serial.MySensorsSerialConnection] - Set skip check on startup to: false
2016-11-20 01:43:15.119 [DEBUG] [col.serial.MySensorsSerialConnection] - Enabling connection watchdog
2016-11-20 01:43:15.126 [DEBUG] [ternal.factory.MySensorsCacheFactory] - Cache file: given_ids.cached exist.
2016-11-20 01:43:15.126 [DEBUG] [ternal.factory.MySensorsCacheFactory] - Cache (given_ids) content: [32, 52, 51, 40, 36, 35]
2016-11-20 01:43:15.126 [DEBUG] [ernal.handler.MySensorsBridgeHandler] - Initialization of the MySensors bridge DONE!
2016-11-20 01:43:15.127 [DEBUG] [col.serial.MySensorsSerialConnection] - Connecting to /dev/ttyUSB21 [baudRate:9600]
2016-11-20 01:43:15.127 [DEBUG] [col.serial.MySensorsSerialConnection] - Final port list: /dev/ttyUSB21
2016-11-20 01:43:15.133 [DEBUG] [col.serial.MySensorsSerialConnection] - Successfully connected to serial port.
2016-11-20 01:43:15.133 [DEBUG] [col.serial.MySensorsSerialConnection] - Waiting 3 seconds to allow correct reset trigger on serial connection opening
2016-11-20 01:43:18.235 [DEBUG] [rs.internal.protocol.MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
2016-11-20 01:43:18.246 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;2;2.0.0
2016-11-20 01:43:18.246 [DEBUG] [col.serial.MySensorsSerialConnection] - Good,Gateway is up and running! (Ver:2.0.0)
2016-11-20 01:43:18.247 [INFO ] [col.serial.MySensorsSerialConnection] - Successfully connected to MySensors Bridge.
2016-11-20 01:43:18.247 [WARN ] [col.serial.MySensorsSerialConnection] - Network Sanity Checker thread disabled from bridge configuration
2016-11-20 01:43:18.258 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 32, chiledId: 0, revertState: false
2016-11-20 01:43:18.259 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 35, chiledId: 0, revertState: false
2016-11-20 01:43:18.259 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 51, chiledId: 3, revertState: false
2016-11-20 01:43:18.259 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 52, chiledId: 3, revertState: false
2016-11-20 01:43:18.259 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 35, chiledId: 3, revertState: false
2016-11-20 01:43:18.260 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 40, chiledId: 0, revertState: true
2016-11-20 01:43:18.260 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 36, chiledId: 3, revertState: false
2016-11-20 01:43:18.260 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 36, chiledId: 1, revertState: false
2016-11-20 01:43:18.260 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 36, chiledId: 0, revertState: false
2016-11-20 01:43:18.260 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 32, chiledId: 3, revertState: false
2016-11-20 01:43:18.261 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 52, chiledId: 4, revertState: false
2016-11-20 01:43:18.261 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 52, chiledId: 5, revertState: false
2016-11-20 01:43:18.262 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 32, chiledId: 1, revertState: false
2016-11-20 01:43:18.262 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 35, chiledId: 1, revertState: false
2016-11-20 01:43:18.263 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 51, chiledId: 4, revertState: false
2016-11-20 01:43:20.379 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:SANCHK:OK
2016-11-20 01:43:28.247 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-11-20 01:43:20.379 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:SANCHK:OK
2016-11-20 01:43:28.247 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-11-20 01:43:38.248 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-11-20 01:43:48.248 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-11-20 01:43:58.249 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-11-20 01:44:01.834 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 32-32-0 s=255,c=3,t=22,pt=5,l=4,sg=0:19562725
2016-11-20 01:44:01.845 [DEBUG] [rs.internal.protocol.MySensorsReader] - 32;255;3;0;22;19562725
2016-11-20 01:44:02.591 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 32-32-0 s=1,c=1,t=0,pt=7,l=5,sg=0:18.2
2016-11-20 01:44:02.591 [DEBUG] [rs.internal.protocol.MySensorsReader] - 32;1;1;0;0;18.2
2016-11-20 01:44:02.683 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 32-32-0 s=2,c=1,t=4,pt=7,l=5,sg=0:1000.8
2016-11-20 01:44:02.683 [DEBUG] [rs.internal.protocol.MySensorsReader] - 32;2;1;0;4;1000.8
2016-11-20 01:44:02.764 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 32-32-0 s=0,c=1,t=1,pt=7,l=5,sg=0:52.1
2016-11-20 01:44:02.774 [DEBUG] [rs.internal.protocol.MySensorsReader] - 32;0;1;0;1;52.1
2016-11-20 01:44:02.855 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 32-32-0 s=2,c=1,t=5,pt=0,l=6,sg=0:cloudy
2016-11-20 01:44:02.856 [DEBUG] [rs.internal.protocol.MySensorsReader] - 32;2;1;0;5;cloudy
2016-11-20 01:44:08.249 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-11-20 01:44:18.249 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-11-20 01:44:20.380 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:SANCHK:OK
2016-11-20 01:44:27.370 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 52-52-0 s=4,c=1,t=0,pt=7,l=5,sg=0:15.1
2016-11-20 01:44:27.370 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:ACK msg
2016-11-20 01:44:27.380 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:SEND 0-0-52-52 s=4,c=1,t=0,pt=7,l=5,sg=0,ft=0,st=ok:15.1
2016-11-20 01:44:27.381 [DEBUG] [rs.internal.protocol.MySensorsReader] - 52;4;1;0;0;15.1
2016-11-20 01:44:27.522 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 52-52-0 s=3,c=1,t=1,pt=7,l=5,sg=0:49.3
2016-11-20 01:44:27.522 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:ACK msg
2016-11-20 01:44:27.563 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;!TSP:MSG:SEND 0-0-52-52 s=3,c=1,t=1,pt=7,l=5,sg=0,ft=0,st=ok:49.3
2016-11-20 01:44:27.564 [DEBUG] [rs.internal.protocol.MySensorsReader] - 52;3;1;0;1;49.3
2016-11-20 01:44:28.250 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-11-20 01:44:30.102 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 51-51-0 s=4,c=1,t=0,pt=7,l=5,sg=0:4.5
2016-11-20 01:44:30.102 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:ACK msg
2016-11-20 01:44:30.113 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:SEND 0-0-51-51 s=4,c=1,t=0,pt=7,l=5,sg=0,ft=0,st=ok:4.5
2016-11-20 01:44:30.113 [DEBUG] [rs.internal.protocol.MySensorsReader] - 51;4;1;0;0;4.5
2016-11-20 01:44:30.204 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 51-51-0 s=3,c=1,t=1,pt=7,l=5,sg=0:91.8
2016-11-20 01:44:30.204 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:ACK msg
2016-11-20 01:44:30.255 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;!TSP:MSG:SEND 0-0-51-51 s=3,c=1,t=1,pt=7,l=5,sg=0,ft=0,st=fail:91.8
2016-11-20 01:44:30.255 [DEBUG] [rs.internal.protocol.MySensorsReader] - 51;3;1;0;1;91.8
2016-11-20 01:44:38.250 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-11-20 01:44:42.816 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 35-35-0 s=255,c=3,t=0,pt=1,l=1,sg=0:57
2016-11-20 01:44:42.826 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:ACK msg
2016-11-20 01:44:42.826 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:SEND 0-0-35-35 s=255,c=3,t=0,pt=1,l=1,sg=0,ft=0,st=ok:57
2016-11-20 01:44:42.837 [DEBUG] [rs.internal.protocol.MySensorsReader] - 35;255;3;0;0;57
2016-11-20 01:44:42.908 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 35-35-0 s=3,c=1,t=38,pt=7,l=5,sg=0:2.6600
2016-11-20 01:44:42.908 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:ACK msg
2016-11-20 01:44:42.918 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:SEND 0-0-35-35 s=3,c=1,t=38,pt=7,l=5,sg=0,ft=0,st=ok:2.6600
2016-11-20 01:44:42.919 [DEBUG] [rs.internal.protocol.MySensorsReader] - 35;3;1;0;38;2.6600
2016-11-20 01:44:43.040 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:READ 35-35-0 s=1,c=1,t=0,pt=7,l=5,sg=0:18.9
2016-11-20 01:44:43.040 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;TSP:MSG:ACK msg
2016-11-20 01:44:43.081 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;9;!TSP:MSG:SEND 0-0-35-35 s=1,c=1,t=0,pt=7,l=5,sg=0,ft=0,st=ok:18.9
2016-11-20 01:44:43.081 [DEBUG] [rs.internal.protocol.MySensorsReader] - 35;1;1;0;0;18.9

As you can see, i recieve messages from the gateway. No items are updated.

FutureCow

This post is deleted!

TimO

@FutureCow Strange, I'll look into it. I suppose I've introduced this bug with the latest refactoring.

ben999

@TimO
Hi Tim
Thanks a lot for your message.
NRF is connected to GPIO pins as per https://www.mysensors.org/build/raspberry
I have run dmesg |grep -i tty as suggested by @Yveaux and i got

[    0.000000] Kernel command line: 8250.nr_uarts=0 dma.dmachans=0x7f35 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2709.boardrev=0xa02082 bcm2709.serial=0xcc3e67e3 smsc95xx.macaddr=B8:27:EB:3E:67:E3 bcm2708_fb.fbswap=1 bcm2709.uart_clock=48000000 vc_mem.mem_base=0x3dc00000 vc_mem.mem_size=0x3f000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[    0.001337] console [tty1] enabled
[    1.781491] 3f201000.uart: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2

I assumed that my serail port would be ttyAMA0
So i wrote my "home.things" file with it:

Bridge mysensors:bridge-ser:gateway [ serialPort="/dev/ttyAMA0", sendDelay=200 ] {
    /** define things connected to that bridge here */  }

This pi@raspberrypi:~ $ screen /dev/ttyAMA0 115200 returns that

[screen is terminating]

Also, when watching the live output from sudo ./bin/mysgw -d i can see that

pi@raspberrypi:~ $ cd MySensors
pi@raspberrypi:~/MySensors $ sudo ./bin/mysgw -d
mysgw: Starting gateway...
mysgw: Protocol version - 2.0.1-beta
mysgw: MCO:BGN:INIT GW,CP=RNNG---,VER=2.0.1-beta
mysgw: TSF:LRT:OK
mysgw: TSM:INIT
mysgw: TSM:INIT:TSP OK
mysgw: TSM:INIT:GW MODE
mysgw: TSM:READY
mysgw: Listening for connections on 0.0.0.0:5003

but when i launch openhab with sudo ./start_debug.sh i see

Launching the openHAB runtime...
Listening for transport dt_socket at address: 5005

5003 vs 5005... I tried that pi@raspberrypi:~/MySensors $ ./configure --my-port=5005 but no luck, I got that in return...

mysgw: accept: Bad file descriptor
mysgw: accept: Bad file descriptor

going forever

bentrik

@TimO said:

GitHub Repo
So I´m very new to OpenHAB, but I´ve tried to bind MySensors for a few days now, and I´m stuck. I´d be really happy if someone could guide me a little further.

-I´ve flashed and installed OpenHABian on my Raspberry. (OpenHAB2)
-Managed to bind my Sonos through the paper ui, so the OpenHAB2 install looks good.
-Now I wish to bind Mysensors on a serial gateway.

Looking at the GitHub install guide it seems as simple as adding the MySensors.jar file to the addons directory, but from what I can see, bindings are not managed like that in OpenHab2? All guiding I read seems to refer to another file structure in OpenHab 1.8.
I managed to find an addons directory in /usr/share/openhab2/addons, but I can´t find a way to copy the .jar file there, as I get permission denied both through WinSCP in sudo mode and terminal ssh. The folder has permission 0775.

Can anyone guide me to thread that describes how to install MySensors on an OpenHABian Raspberry installation?

TimO

@bentrik said:

I managed to find an addons directory in /usr/share/openhab2/addons, but I can´t find a way to copy the .jar file there, as I get permission denied both through WinSCP in sudo mode and terminal ssh. The folder has permission 0775.

That is the correct directory if you installed OH2 via .deb. Seems like you are using a user in WinSCP that is not allowed to write to the directory above. To circumvent this:

Copy the binding jar to /tmp.
Login via ssh and execute:

sudo cp /tmp/org.openhab.binding.mysensors-2.0.0-SNAPSHOT.jar /usr/share/openhab2/addons/

and

sudo chmod openhab.openhab /usr/share/openhab2/addons/org.openhab.binding.mysensors-2.0.0-SNAPSHOT.jar

OH2 is started/stopped/restarted with

service openhab2 start/stop/restart

To log into the karaf console do:

ssh openhab@localhost -p 8101

Password is: habopen

Follow the guide/wiki from:

In the console enter feature:install openhab-transport-serial

TimO

@ben999

If you are using the RPi gateway with the options you provided above:

sudo ./bin/mysgw -d

You need to configure the OH2 binding to connect to a ethernet gateway (via localhost, 127.0.0.1 and port 5003), don't use the serial gateway. You are able to confirm this if you execute a "telnet localhost 5003" on the RPi and should be see the messages incoming from the node.

FutureCow

I did some testing with older and newer version:

OpenHAB #457, MySensor_Binding Aug2016, Text conf: No problems
OpenHAB #457, MySensor_Binding Nov2016, Text conf: No problems
OpenHAB #457, MySensor_Binding Aug2016, PaperUI conf: No autodiscovery, Manual Add: No problems
OpenHAB #457, MySensor_Binding Nov2016, PaperUI conf: No autodiscovery, Manual Add: No problems

OpenHAB #603, MySensor_Binding Aug2016, Text conf: Doesn't Work!
OpenHAB #603, MySensor_Binding Nov2016, Text conf: Doesn't work!
OpenHAB #603, MySensor_Binding Aug2016, PaperUI conf: No autodiscovery, Manual Add: Doesn't work!
OpenHAB #603, MySensor_Binding Nov2016, PaperUI conf: No autodiscovery, Manual Add: Doesn't work!

Doesn't work! means the gateway is working, I receive messages, but the items doesn't get updated.
Also restarting openhab/mysensor binding doesnt solve the problem.

TimO

@FutureCow Thanks for testing! There definiatly is a bug and slowly I'm getting a grip on it. The annoying thing is: in my development environment everything works smooth, so I updated my production environment and voila there is the problem: no thing updates.

It looks like a timing issue on initialization of the bridge/gateway. I'll dig deeper!

The topic autodiscovery will follow, I've not spent much time in testing this feature as it was of no use till lately. Now PaperUI/Habpanel are getting the functionality that makes it usable and will make the big difference to OpenHAB 1.

bathoryr

I also have similar problems, after upgrade OH to latest snapshot yesterday. All things remain in offline status. Discovery is working when I hit "Search for things" from Paper UI and force presentation/reset on some sensor.

21:23:12.982 [DEBUG] [org.openhab.binding.mysensors       ] - BundleEvent STARTING - org.openhab.binding.mysensors
21:23:13.062 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.mysensors.internal.factory.MySensorsHandlerFactory, component.id=252, service.id=400, service.bundleid=198, service.scope=bundle} - org.openhab.binding.mysensors
21:23:13.082 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=401, service.bundleid=198, service.scope=singleton} - org.openhab.binding.mysensors
21:23:13.121 [DEBUG] [org.openhab.binding.mysensors       ] - BundleEvent STARTED - org.openhab.binding.mysensors
21:23:13.548 [DEBUG] [ernal.handler.MySensorsBridgeHandler] - Initialization of the MySensors bridge
21:23:13.551 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Set skip check on startup to: false
21:23:13.552 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Enabling connection watchdog
21:23:13.555 [DEBUG] [ternal.factory.MySensorsCacheFactory] - Cache file: given_ids.cached exist.
21:23:13.557 [DEBUG] [ternal.factory.MySensorsCacheFactory] - Cache (given_ids) content: [5, 12, 7, 10, 1, 9, 3, 8, 30, 6, 24]
21:23:13.559 [DEBUG] [ernal.handler.MySensorsBridgeHandler] - Initialization of the MySensors bridge DONE!
21:23:13.549 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-eth:gateway' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
21:23:13.571 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Connecting to IP bridge [127.0.0.1:5003]
21:23:13.596 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;14;Gateway startup complete.
21:23:13.598 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;0;0;18;2.0.1-beta
21:23:13.778 [DEBUG] [rs.internal.protocol.MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
21:23:13.797 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;2;2.0.1-beta
21:23:13.800 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Good,Gateway is up and running! (Ver:2.0.1-beta)
21:23:13.813 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-eth:gateway' changed from INITIALIZING to ONLINE
21:23:13.828 [INFO ] [al.protocol.ip.MySensorsIpConnection] - Successfully connected to MySensors Bridge.
21:23:13.830 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 12, chiledId: 1, revertState: false
21:23:13.830 [WARN ] [al.protocol.ip.MySensorsIpConnection] - Network Sanity Checker thread disabled from bridge configuration
21:23:13.855 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:power:gateway:house_power_12_1' changed from INITIALIZING to OFFLINE
21:23:13.856 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:power:gateway:house_power_12_1' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
21:23:13.882 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 24, chiledId: 1, revertState: false
21:23:13.892 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:dimmer:gateway:Dimmer_24_1' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
21:23:13.892 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 5, chiledId: 1, revertState: false
21:23:13.899 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:dimmer:gateway:living_room_5_1' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
21:23:13.904 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:dimmer:gateway:Dimmer_24_1' changed from INITIALIZING to OFFLINE
21:23:13.926 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:dimmer:gateway:living_room_5_1' changed from INITIALIZING to OFFLINE
21:23:23.832 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:23:25.599 [DEBUG] [rs.internal.protocol.MySensorsReader] - 12;1;1;0;17;516
21:23:25.624 [DEBUG] [rs.internal.protocol.MySensorsReader] - 12;1;1;0;24;550307
21:23:25.639 [DEBUG] [rs.internal.protocol.MySensorsReader] - 12;1;1;0;18;55.0307
21:23:29.103 [DEBUG] [rs.internal.protocol.MySensorsReader] - 7;1;1;0;0;19.8
21:23:29.119 [DEBUG] [rs.internal.protocol.MySensorsReader] - 7;255;3;0;22;1208410

Also, when I stop bundle from karaf console, this error appears in log:

21:24:37.371 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=401, service.bundleid=198, service.scope=singleton} - org.openhab.binding.mysensors
21:24:37.379 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:dimmer:gateway:Dimmer_24_1' changed from OFFLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
21:24:37.397 [DEBUG] [ernal.handler.MySensorsBridgeHandler] - Disposing of the MySensors bridge
21:24:37.399 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Destroying connection
21:24:37.400 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Disconnecting from IP bridge ...
21:24:37.401 [DEBUG] [rs.internal.protocol.MySensorsWriter] - Stopping Writer thread
21:24:37.413 [ERROR] [rs.internal.protocol.MySensorsWriter] - (java.lang.InterruptedException) on writing from serial port, message: class org.openhab.binding.mysensors.internal.protocol.ip.MySensorsIpWriter
21:24:37.414 [DEBUG] [rs.internal.protocol.MySensorsReader] - Stopping Reader thread
21:24:37.422 [ERROR] [rs.internal.protocol.MySensorsReader] - (java.lang.InterruptedException: sleep interrupted) on reading from serial port, message: class org.openhab.binding.mysensors.internal.protocol.ip.MySensorIpReader
21:24:37.422 [DEBUG] [ternal.factory.MySensorsCacheFactory] - Cache file: given_ids.cached exist.
21:24:37.426 [DEBUG] [ternal.factory.MySensorsCacheFactory] - Cache (given_ids) content: [5, 12, 7, 10, 1, 9, 3, 8, 30, 6, 24]
21:24:37.433 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-eth:gateway' changed from ONLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
21:24:37.429 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while disposing handler of thing 'mysensors:bridge-eth:gateway': java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
	at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_65]
	at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_65]
	at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:186)
	at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:79)
	at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:63)
	at org.eclipse.smarthome.core.thing.internal.ThingManager.doDisposeHandler(ThingManager.java:858)
	at org.eclipse.smarthome.core.thing.internal.ThingManager.disposeHandler(ThingManager.java:848)
	at org.eclipse.smarthome.core.thing.internal.ThingManager.removeThingHandlerFactory(ThingManager.java:1045)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_65]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_65]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_65]
	at java.lang.reflect.Method.invoke(Method.java:497)[:1.8.0_65]
	at org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.helper.BindMethod.invoke(BindMethod.java:41)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.DependencyManager.invokeUnbindMethod(DependencyManager.java:1774)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeUnbindMethod(SingleComponentManager.java:393)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:364)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:295)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1241)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1136)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.untrack(ServiceTracker.java:996)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1175)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:120)[34:org.apache.felix.scr:2.0.2]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]

ben999

@TimO
Thank you one more time Tim

So i went ahead and replaced

Bridge mysensors:bridge-ser:gateway [ serialPort="/dev/ttyAMA0", sendDelay=200 ]

with

Bridge mysensors:bridge-eth:gateway [ ipAddress="127.0.0.1", tcpPort=5003, sendDelay=200 ]

together with

pi@raspberrypi:/usr/share/openhab2 $ ./configure --my-gateway=ethernet --my-port=5003 --my-serial-port=/dev/ttyAMA0

pi@raspberrypi:/ $ telnet 127.0.0.1 5003 returns what is expected i guess :

Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
0;255;3;0;14;Gateway startup complete.
0;255;0;0;18;2.0.1-beta
1;255;0;0;17;2.0.0
1;255;3;0;11;TemperatureAndHumidity
1;255;3;0;12;1.1
1;0;0;0;7;
1;1;0;0;6;
1;1;1;0;0;19.1
1;0;1;0;1;62.5

But still, there must be a missing link : neither in PaperUi nor openHab on iOS i get temp and humidity readings...

This is my OH2 log:tail

06:26:19.597 [DEBUG] [e.internal.WriterInterceptorExecutor] - Message body writer (class com.eclipsesource.jaxrs.provider.gson.GsonProvider) is trying to close the entity output stream. Not closing.
06:26:19.598 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1785907[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,740,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@113ab9] generate: NEED_HEADER (null,[p=0,l=740,c=8192,r=740],true)@START
06:26:19.600 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1785907[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,740,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@113ab9] generate: FLUSH ([p=0,l=105,c=8192,r=105],[p=0,l=740,c=8192,r=740],true)@COMPLETING
06:26:19.601 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@af70aa{IDLE} [HeapByteBuffer@2a5ea9[p=0,l=105,c=8192,r=105]={<<<HTTP/1.1 200 OK\r\n....v20151106)\r\n\r\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\x00\x00},HeapByteBuffer@1ef785[p=0,l=740,c=8192,r=740]={<<<{"id":"_default",...idgets":[]}]}]}>>>\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\x00\x00}]
06:26:19.602 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@af70aa{WRITING}:IDLE-->WRITING
06:26:19.604 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,W,128/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,58/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,0 of -1},g=HttpGenerator{s=COMPLETING},c=HttpChannelOverHttp@170a7cc{r=25,c=true,a=DISPATCHED,uri=/rest/sitemaps/_default/_default}] flush enter [java.nio.HeapByteBuffer[pos=0 lim=105 cap=8192], java.nio.HeapByteBuffer[pos=0 lim=740 cap=8192]]
06:26:19.607 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=-1/874,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,W,131/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,61/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,0 of -1},g=HttpGenerator{s=COMPLETING},c=HttpChannelOverHttp@170a7cc{r=25,c=true,a=DISPATCHED,uri=/rest/sitemaps/_default/_default}] wrap Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 845 bytesProduced = 874
06:26:19.610 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,W,134/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,65/30000,SslConnection}{io=0,kio=0,kro=1} OK HeapByteBuffer@1543b4c[p=0,l=874,c=17408,r=874]={<<<\x17\x03\x03\x03e\x00\x00\x00\x00\x00\x00\x00\x19\xC1\xE8\x8c-...g\xEbkEP\x05\xD7D\x1d\xD51\xA4\x92\x86Y>>>\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\x00\x00}
06:26:19.613 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 874 SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,68/30000,SslConnection}{io=0,kio=0,kro=1}
06:26:19.615 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=-1/0,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,W,140/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,0/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,0 of -1},g=HttpGenerator{s=COMPLETING},c=HttpChannelOverHttp@170a7cc{r=25,c=true,a=DISPATCHED,uri=/rest/sitemaps/_default/_default}] flush exit, consumed 845
06:26:19.617 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@af70aa{IDLE}:WRITING-->IDLE
06:26:19.619 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1785907[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,740,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@113ab9] generate: DONE ([p=105,l=105,c=8192,r=0],[p=740,l=740,c=8192,r=0],true)@END
06:26:19.621 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ o.e.j.s.h.ContextHandler@2b17f5{/static,null,AVAILABLE}
06:26:19.622 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.201611041332 [100], contextID=default]}
06:26:19.623 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.201611041332 [137], contextID=default]}
06:26:19.624 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.201611041332 [138], contextID=default]}
06:26:19.625 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@715e88}
06:26:19.626 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.201611041332 [186], contextID=default]}
06:26:19.627 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.classic_0.9.0.201611041332 [187], contextID=default]}
06:26:19.629 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.201611041332 [188], contextID=default]}
06:26:19.630 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.io.rest.docs_2.0.0.201611062131 [189], contextID=default]}
06:26:19.631 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.0.0.201611062131 [192], contextID=default]}
06:26:19.632 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.0.0.201611062131 [168], contextID=default]}
06:26:19.632 [DEBUG] [org.eclipse.jetty.server.Server     ] - RESPONSE /rest/sitemaps/_default/_default  200 handled=true
06:26:19.633 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@8beceb{s=DISPATCHED i=true a=null} unhandle DISPATCHED
06:26:19.635 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - reset HttpParser{s=END,0 of -1}
06:26:19.636 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - END --> START
06:26:19.637 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=} handle exit, result COMPLETE
06:26:19.638 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,163/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,23/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] fill enter
06:26:19.640 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,24/30000,SslConnection}{io=0,kio=0,kro=1}
06:26:19.641 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,166/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,26/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] filled 0 encrypted bytes
06:26:19.643 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,168/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,28/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] unwrap Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
06:26:19.645 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,170/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,30/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] fill exit
06:26:19.647 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,171/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,31/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] fill enter
06:26:19.648 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,33/30000,SslConnection}{io=0,kio=0,kro=1}
06:26:19.650 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,174/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,34/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] filled 0 encrypted bytes
06:26:19.652 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,176/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,36/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] unwrap Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
06:26:19.654 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,178/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,38/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] fill exit
06:26:19.654 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@ad25df[p=0,l=0,c=17408,r=0]={<<<>>>GET /rest/sitemap...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
06:26:19.656 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,181/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,41/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}]
06:26:19.658 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING-->FILLING_FILL_INTERESTED HttpConnection@5d1aa0[FILLING_FILL_INTERESTED,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,183/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,43/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}]
06:26:19.660 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING_FILL_INTERESTED-->FILL_INTERESTED HttpConnection@5d1aa0[FILL_INTERESTED,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,184/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,44/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}]
06:26:19.661 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested SslConnection@d43845{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@5d1aa0[FILL_INTERESTED,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,R,-,1/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,46/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}]
06:26:19.663 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - IDLE-->FILL_INTERESTED SslConnection@d43845{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@5d1aa0[FILL_INTERESTED,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,R,-,3/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,48/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}]
06:26:19.664 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 0 -> 1 for SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,R,-,0/30000,SslConnection}{io=1,kio=0,kro=1}
06:26:19.665 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@2ea554
06:26:19.666 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 0/1 selected
06:26:19.667 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@2ea554
06:26:19.667 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 0 -> 1 on SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,R,-,3/30000,SslConnection}{io=1,kio=1,kro=1}
06:26:19.667 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
06:26:19.714 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 1/1 selected
06:26:19.714 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 1 -> 0 on SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,R,-,50/30000,SslConnection}{io=1,kio=0,kro=1}
06:26:19.715 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 1 -> 0 for SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,R,-,51/30000,SslConnection}{io=0,kio=0,kro=1}
06:26:19.715 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@2ea554
06:26:19.716 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILL_INTERESTED-->FILLING SslConnection@d43845{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@5d1aa0[FILL_INTERESTED,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,R,-,56/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,52/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}]
06:26:19.717 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - onFillable enter DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,R,-,57/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,53/30000,SslConnection}{io=0,kio=0,kro=1}
06:26:19.718 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILL_INTERESTED-->FILLING HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,58/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,54/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}]
06:26:19.719 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - onFillable exit DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,59/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,55/30000,SslConnection}{io=0,kio=0,kro=1}
06:26:19.720 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,59/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,55/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] onFillable HttpChannelState@8beceb{s=IDLE i=true a=null}
06:26:19.721 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING-->IDLE SslConnection@d43845{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,60/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,56/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}]
06:26:19.721 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,60/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,56/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] fill enter
06:26:19.721 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@2ea554
06:26:19.722 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
06:26:19.722 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 515 SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,57/30000,SslConnection}{io=0,kio=0,kro=1}
06:26:19.726 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=515/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,62/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,2/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] filled 515 encrypted bytes
06:26:19.730 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,70/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,8/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] unwrap Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 515 bytesProduced = 486
06:26:19.733 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@d43845{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@5d1aa0[FILLING,DecryptedEndPoint@12d4ea{/192.168.1.24:54399<->8443,Open,in,out,-,-,73/30000,HttpConnection}->SelectChannelEndPoint@bd1cb6{/192.168.1.24:54399<->8443,Open,in,out,-,-,11/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@170a7cc{r=25,c=false,a=IDLE,uri=}] fill exit
06:26:19.735 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@19b0494[p=0,l=486,c=17408,r=486]={<<<GET /rest/sitemap...rwin/16.1.0\r\n\r\n>>>\xBd\xE2\xFb\xC2E\x82\xF6\xD7\xEf\x82(\xE4\xBd`i\xDf\xBd...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
06:26:19.737 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> SPACE1
06:26:19.738 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE1 --> URI
06:26:19.740 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - URI --> SPACE2
06:26:19.740 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE2 --> REQUEST_VERSION
06:26:19.741 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - REQUEST_VERSION --> HEADER
06:26:19.742 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
06:26:19.743 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
06:26:19.744 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
06:26:19.745 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
06:26:19.746 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
06:26:19.746 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
06:26:19.747 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
06:26:19.748 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
06:26:19.748 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
06:26:19.749 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
06:26:19.750 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
06:26:19.751 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
06:26:19.752 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
06:26:19.752 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
06:26:19.753 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
06:26:19.754 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
06:26:19.755 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
06:26:19.755 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
06:26:19.756 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
06:26:19.756 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
06:26:19.757 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
06:26:19.758 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
06:26:19.759 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
06:26:19.759 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
06:26:19.760 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
06:26:19.761 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
06:26:19.761 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
06:26:19.762 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
06:26:19.763 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> END
06:26:19.764 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@170a7cc{r=26,c=false,a=IDLE,uri=/rest/sitemaps/_default/_default} messageComplete
06:26:19.765 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@1f4ee36 EOF
06:26:19.765 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@170a7cc{r=26,c=false,a=IDLE,uri=/rest/sitemaps/_default/_default} handle enter
06:26:19.766 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@8beceb{s=IDLE i=true a=null} handling IDLE
06:26:19.767 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@170a7cc{r=26,c=false,a=DISPATCHED,uri=/rest/sitemaps/_default/_default} action REQUEST_DISPATCH
06:26:19.769 [DEBUG] [org.eclipse.jetty.server.Server     ] - REQUEST GET /rest/sitemaps/_default/_default on HttpChannelOverHttp@170a7cc{r=26,c=false,a=DISPATCHED,uri=/rest/sitemaps/_default/_default}
06:26:19.769 [DEBUG] [ax.web.service.spi.model.ServerModel] - Matching [/rest/sitemaps/_default/_default]...
06:26:19.770 [DEBUG] [ax.web.service.spi.model.ServerModel] - Path [/rest/sitemaps/_default/_default] matched to {pattern=/rest/.*,model=ServletModel{id=org.ops4j.pax.web.service.spi.model.ServletModel-2,name=org.ops4j.pax.web.service.spi.model.ServletModel-2,urlPatterns=[/rest/*],alias=/rest,servlet=com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge@f40c7,initParams={},context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-1,name=,httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default],contextParams={},virtualHosts={},connectors={}}}}
06:26:19.771 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]}
06:26:19.772 [DEBUG] [.jetty.server.handler.ContextHandler] - context=||/rest/sitemaps/_default/_default @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]}
06:26:19.773 [DEBUG] [org.eclipse.jetty.server.session    ] - sessionManager=org.ops4j.pax.web.service.jetty.internal.LateInvalidatingHashSessionManager@18d27f3
06:26:19.774 [DEBUG] [org.eclipse.jetty.server.session    ] - session=null
06:26:19.775 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - servlet |/rest|/sitemaps/_default/_default -> org.ops4j.pax.web.service.spi.model.ServletModel-2@378be0fa==com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge,-1,true
06:26:19.775 [DEBUG] [ce.jetty.internal.HttpServiceContext] - Handling request for [/rest/sitemaps/_default/_default] using http context [DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]]
06:26:19.776 [DEBUG] [y.internal.HttpServiceServletHandler] - handling request org.ops4j.pax.web.service.jetty.internal.HttpServiceRequestWrapper@edd379, org.ops4j.pax.web.service.jetty.internal.HttpServiceResponseWrapper@662e02
06:26:19.777 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - chain=null

repeated every few seconds... anything can be understood from that?

TimO

Ok, here is the corrected jar file: LINK

The things now should update.

I've tested it with the current snapshot on two systems / mysensors environments. I've not tested it against the curren testing (beta4). It should work, but it may throw exceptions on startup.

At the moment please only update if you expierence problems. I would like to ensure the binding is now working.

FutureCow

Thanks, the new version is working nice. only your link didn't work for me, i used this one:
https://github.com/tobof/openhab2-addons/blob/MySensors/addons/binding/org.openhab.binding.mysensors/target/org.openhab.binding.mysensors-2.0.0-SNAPSHOT.jar?raw=true

ben999

@TimO
Thank you for that new jar file.
Gateway is "online" in PaperUI
Sensors are "Uninitialised"
PaperUI says Status: UNINITIALIZED - HANDLER_INITIALIZING_ERROR org.eclipse.smarthome.core.thing.Bridge.getHandler()Lorg/eclipse/smarthome/core/thing/binding/BridgeHandler;
I have added these sensors manually to thing file:

Bridge mysensors:bridge-eth:gateway [ ipAddress="127.0.0.1", tcpPort=5003, sendDelay=200, skipStartupCheck=true ] {
        humidity        bathHum01               [ nodeId="1", childId="0" ]
        temperature     bathTemp01              [ nodeId="1", childId="1" ]    }

Here is log file from OH2

22:06:55.465 [DEBUG] [io.socket.engineio.client.Socket    ] - writing ping packet - expecting pong within 60000ms
22:06:55.466 [DEBUG] [io.socket.engineio.client.Socket    ] - flushing 1 packets in socket
22:06:55.509 [DEBUG] [io.socket.engineio.client.Socket    ] - socket received: type 'pong', data 'null'
22:07:04.487 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
22:07:07.682 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@310200{/192.168.1.9:60520<->8080,Open,in,out,-,-,30000/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
22:07:07.683 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@310200{/192.168.1.9:60520<->8080,Open,in,out,-,-,30002/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout expired
22:07:07.684 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - ignored: WriteFlusher@82249d{IDLE} java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
22:07:07.685 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SelectChannelEndPoint@310200{/192.168.1.9:60520<->8080,Open,in,out,-,-,30003/30000,HttpConnection}{io=0,kio=0,kro=1}
22:07:09.977 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,29439/30000,SslConnection}{io=0,kio=0,kro=1} idle timeout check, elapsed: 29439 ms, remaining: 561 ms
22:07:10.540 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,30001/30000,SslConnection}{io=0,kio=0,kro=1} idle timeout check, elapsed: 30001 ms, remaining: -1 ms
22:07:10.541 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,30002/30000,SslConnection}{io=0,kio=0,kro=1} idle timeout expired
22:07:10.541 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - ignored: WriteFlusher@f4107c{IDLE} java.util.concurrent.TimeoutException: Idle timeout expired: 30001/30000 ms
22:07:10.542 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,30004/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:10.884 [DEBUG] [e.internal.WriterInterceptorExecutor] - Message body writer (class com.eclipsesource.jaxrs.provider.gson.GsonProvider) is trying to close the entity output stream. Not closing.
22:07:10.886 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@ad3ff7[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,1051,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@b60904] generate: NEED_HEADER (null,[p=0,l=1051,c=8192,r=1051],true)@START
22:07:10.887 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@ad3ff7[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,1051,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@b60904] generate: FLUSH ([p=0,l=106,c=8192,r=106],[p=0,l=1051,c=8192,r=1051],true)@COMPLETING
22:07:10.889 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@18a5ae6{IDLE} [HeapByteBuffer@107873[p=0,l=106,c=8192,r=106]={<<<HTTP/1.1 200 OK\r\n....v20151106)\r\n\r\n>>> chunked\r\nServer:...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@6612b4[p=0,l=1051,c=8192,r=1051]={<<<{"id":"0000","tit..."widgets":[]}]}>>>\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\x00\x00}]
22:07:10.892 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@18a5ae6{WRITING}:IDLE-->WRITING
22:07:10.895 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,W,30371/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,353/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,0 of -1},g=HttpGenerator{s=COMPLETING},c=HttpChannelOverHttp@d19aaf{r=38,c=true,a=DISPATCHED,uri=/rest/sitemaps/_default/0000}] flush enter [java.nio.HeapByteBuffer[pos=0 lim=106 cap=8192], java.nio.HeapByteBuffer[pos=0 lim=1051 cap=8192]]
22:07:10.901 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/1186,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,W,30377/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,358/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,0 of -1},g=HttpGenerator{s=COMPLETING},c=HttpChannelOverHttp@d19aaf{r=38,c=true,a=DISPATCHED,uri=/rest/sitemaps/_default/0000}] wrap Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 1157 bytesProduced = 1186
22:07:10.903 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,W,30379/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,361/30000,SslConnection}{io=0,kio=0,kro=1} OK HeapByteBuffer@eb6978[p=0,l=1186,c=17408,r=1186]={<<<\x17\x03\x03\x04\x9d\x00\x00\x00\x00\x00\x00\x00&\xFe3\xE3|...\xFe$\xE1\xF9J\xE06\xE9\xE96_=\x9a\xAa\x0c>>>\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\x00\x00}
22:07:10.906 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 1186 SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,363/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:10.908 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/0,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,W,30384/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,1/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,0 of -1},g=HttpGenerator{s=COMPLETING},c=HttpChannelOverHttp@d19aaf{r=38,c=true,a=DISPATCHED,uri=/rest/sitemaps/_default/0000}] flush exit, consumed 1157
22:07:10.910 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@18a5ae6{IDLE}:WRITING-->IDLE
22:07:10.912 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@ad3ff7[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,1051,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@b60904] generate: DONE ([p=106,l=106,c=8192,r=0],[p=1051,l=1051,c=8192,r=0],true)@END
22:07:10.915 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ o.e.j.s.h.ContextHandler@1f3fece{/static,null,AVAILABLE}
22:07:10.916 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.201611041332 [100], contextID=default]}
22:07:10.917 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.201611041332 [137], contextID=default]}
22:07:10.918 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.201611041332 [138], contextID=default]}
22:07:10.919 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@14870c1}
22:07:10.919 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.201611041332 [186], contextID=default]}
22:07:10.920 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.classic_0.9.0.201611041332 [187], contextID=default]}
22:07:10.921 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.201611041332 [188], contextID=default]}
22:07:10.921 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.io.rest.docs_2.0.0.201611062131 [189], contextID=default]}
22:07:10.922 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.0.0.201611062131 [192], contextID=default]}
22:07:10.923 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.0.0.201611062131 [168], contextID=default]}
22:07:10.924 [DEBUG] [org.eclipse.jetty.server.Server     ] - RESPONSE /rest/sitemaps/_default/0000  200 handled=true
22:07:10.925 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@6e53d6{s=DISPATCHED i=true a=null} unhandle DISPATCHED
22:07:10.926 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - reset HttpParser{s=END,0 of -1}
22:07:10.926 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - END --> START
22:07:10.927 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=} handle exit, result COMPLETE
22:07:10.929 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,30405/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,22/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] fill enter
22:07:10.931 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,23/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:10.933 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,30409/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,25/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] filled 0 encrypted bytes
22:07:10.935 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,30411/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,27/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] unwrap Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
22:07:10.937 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,30413/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,29/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] fill exit
22:07:10.939 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,30415/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,32/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] fill enter
22:07:10.941 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,33/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:10.942 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,30419/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,35/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] filled 0 encrypted bytes
22:07:10.945 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,30421/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,37/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] unwrap Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
22:07:10.947 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,30423/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,39/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] fill exit
22:07:10.948 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@1ac887b[p=0,l=0,c=17408,r=0]={<<<>>>GET /rest/sitemap...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
22:07:10.949 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,30426/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,42/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}]
22:07:10.951 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING-->FILLING_FILL_INTERESTED HttpConnection@12c6b19[FILLING_FILL_INTERESTED,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,30427/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,44/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}]
22:07:10.953 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING_FILL_INTERESTED-->FILL_INTERESTED HttpConnection@12c6b19[FILL_INTERESTED,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,30429/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,46/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}]
22:07:10.955 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILL_INTERESTED,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,R,-,0/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,48/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}]
22:07:10.958 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - IDLE-->FILL_INTERESTED SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILL_INTERESTED,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,R,-,3/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,50/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}]
22:07:10.959 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 0 -> 1 for SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,R,-,0/30000,SslConnection}{io=1,kio=0,kro=1}
22:07:10.960 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d2164a
22:07:10.961 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 0/1 selected
22:07:10.961 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d2164a
22:07:10.962 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 0 -> 1 on SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,R,-,3/30000,SslConnection}{io=1,kio=1,kro=1}
22:07:10.962 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
22:07:11.035 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 1/1 selected
22:07:11.036 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 1 -> 0 on SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,R,-,78/30000,SslConnection}{io=1,kio=0,kro=1}
22:07:11.036 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 1 -> 0 for SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,R,-,78/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:11.037 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d2164a
22:07:11.038 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILL_INTERESTED-->FILLING SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILL_INTERESTED,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,R,-,83/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,79/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}]
22:07:11.038 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - onFillable enter DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,R,-,84/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,80/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:11.039 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILL_INTERESTED-->FILLING HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,85/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,81/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}]
22:07:11.040 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - onFillable exit DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,86/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,82/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:11.041 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,86/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,82/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] onFillable HttpChannelState@6e53d6{s=IDLE i=true a=null}
22:07:11.041 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING-->IDLE SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,87/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,83/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}]
22:07:11.042 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,87/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,83/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] fill enter
22:07:11.042 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d2164a
22:07:11.042 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
22:07:11.042 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 473 SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,84/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:11.043 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=473/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,89/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,1/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] filled 473 encrypted bytes
22:07:11.045 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,91/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,3/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] unwrap Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 473 bytesProduced = 444
22:07:11.046 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,92/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,4/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=38,c=false,a=IDLE,uri=}] fill exit
22:07:11.047 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@c998ba[p=0,l=444,c=17408,r=444]={<<<GET /rest/sitemap...rwin/16.1.0\r\n\r\n>>>.0 CFNetwork/808....\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
22:07:11.047 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> SPACE1
22:07:11.047 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE1 --> URI
22:07:11.048 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - URI --> SPACE2
22:07:11.048 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE2 --> REQUEST_VERSION
22:07:11.048 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - REQUEST_VERSION --> HEADER
22:07:11.048 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.049 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.049 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
22:07:11.049 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
22:07:11.049 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
22:07:11.050 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.050 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.050 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.050 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.050 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.050 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.051 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.051 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.051 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.051 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.051 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.052 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
22:07:11.052 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
22:07:11.052 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
22:07:11.052 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.052 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.053 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.053 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.053 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.053 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> END
22:07:11.054 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=/rest/sitemaps/_default/0000} messageComplete
22:07:11.054 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@15ca2 EOF
22:07:11.055 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=/rest/sitemaps/_default/0000} handle enter
22:07:11.055 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@6e53d6{s=IDLE i=true a=null} handling IDLE
22:07:11.056 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@d19aaf{r=39,c=false,a=DISPATCHED,uri=/rest/sitemaps/_default/0000} action REQUEST_DISPATCH
22:07:11.056 [DEBUG] [org.eclipse.jetty.server.Server     ] - REQUEST GET /rest/sitemaps/_default/0000 on HttpChannelOverHttp@d19aaf{r=39,c=false,a=DISPATCHED,uri=/rest/sitemaps/_default/0000}
22:07:11.057 [DEBUG] [ax.web.service.spi.model.ServerModel] - Matching [/rest/sitemaps/_default/0000]...
22:07:11.057 [DEBUG] [ax.web.service.spi.model.ServerModel] - Path [/rest/sitemaps/_default/0000] matched to {pattern=/rest/.*,model=ServletModel{id=org.ops4j.pax.web.service.spi.model.ServletModel-2,name=org.ops4j.pax.web.service.spi.model.ServletModel-2,urlPatterns=[/rest/*],alias=/rest,servlet=com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge@1efe36d,initParams={},context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-1,name=,httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default],contextParams={},virtualHosts={},connectors={}}}}
22:07:11.057 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]}
22:07:11.058 [DEBUG] [.jetty.server.handler.ContextHandler] - context=||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]}
22:07:11.058 [DEBUG] [org.eclipse.jetty.server.session    ] - sessionManager=org.ops4j.pax.web.service.jetty.internal.LateInvalidatingHashSessionManager@1a5ce14
22:07:11.059 [DEBUG] [org.eclipse.jetty.server.session    ] - session=null
22:07:11.059 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - servlet |/rest|/sitemaps/_default/0000 -> org.ops4j.pax.web.service.spi.model.ServletModel-2@378be0fa==com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge,-1,true
22:07:11.059 [DEBUG] [ce.jetty.internal.HttpServiceContext] - Handling request for [/rest/sitemaps/_default/0000] using http context [DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]]
22:07:11.060 [DEBUG] [y.internal.HttpServiceServletHandler] - handling request org.ops4j.pax.web.service.jetty.internal.HttpServiceRequestWrapper@5ce2b2, org.ops4j.pax.web.service.jetty.internal.HttpServiceResponseWrapper@97896c
22:07:11.060 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - chain=null
22:07:11.073 [DEBUG] [e.internal.WriterInterceptorExecutor] - Message body writer (class com.eclipsesource.jaxrs.provider.gson.GsonProvider) is trying to close the entity output stream. Not closing.

ben999

22:07:11.075 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@ad3ff7[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,1051,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1ccbd33] generate: NEED_HEADER (null,[p=0,l=1051,c=8192,r=1051],true)@START
22:07:11.075 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@ad3ff7[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,1051,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1ccbd33] generate: FLUSH ([p=0,l=106,c=8192,r=106],[p=0,l=1051,c=8192,r=1051],true)@COMPLETING
22:07:11.076 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@18a5ae6{IDLE} [HeapByteBuffer@107873[p=0,l=106,c=8192,r=106]={<<<HTTP/1.1 200 OK\r\n....v20151106)\r\n\r\n>>> chunked\r\nServer:...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@193feb4[p=0,l=1051,c=8192,r=1051]={<<<{"id":"0000","tit..."widgets":[]}]}>>>\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\x00\x00}]
22:07:11.076 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@18a5ae6{WRITING}:IDLE-->WRITING
22:07:11.077 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,W,123/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,35/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,0 of -1},g=HttpGenerator{s=COMPLETING},c=HttpChannelOverHttp@d19aaf{r=39,c=true,a=DISPATCHED,uri=/rest/sitemaps/_default/0000}] flush enter [java.nio.HeapByteBuffer[pos=0 lim=106 cap=8192], java.nio.HeapByteBuffer[pos=0 lim=1051 cap=8192]]
22:07:11.102 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/1186,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,W,147/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,60/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,0 of -1},g=HttpGenerator{s=COMPLETING},c=HttpChannelOverHttp@d19aaf{r=39,c=true,a=DISPATCHED,uri=/rest/sitemaps/_default/0000}] wrap Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 1157 bytesProduced = 1186
22:07:11.103 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,W,148/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,61/30000,SslConnection}{io=0,kio=0,kro=1} OK HeapByteBuffer@eb6978[p=0,l=1186,c=17408,r=1186]={<<<\x17\x03\x03\x04\x9d\x00\x00\x00\x00\x00\x00\x00']\x1a(\xA4...\x94_\xF6\x11\x13PZf&0^\x1a\xC5c\x85>>>\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\x00\x00}
22:07:11.104 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 1186 SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,61/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:11.105 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/0,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,W,150/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,0/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,0 of -1},g=HttpGenerator{s=COMPLETING},c=HttpChannelOverHttp@d19aaf{r=39,c=true,a=DISPATCHED,uri=/rest/sitemaps/_default/0000}] flush exit, consumed 1157
22:07:11.105 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@18a5ae6{IDLE}:WRITING-->IDLE
22:07:11.106 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@ad3ff7[PROCESSING][i=ResponseInfo{HTTP/1.1 200 OK,1051,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1ccbd33] generate: DONE ([p=106,l=106,c=8192,r=0],[p=1051,l=1051,c=8192,r=0],true)@END
22:07:11.107 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ o.e.j.s.h.ContextHandler@1f3fece{/static,null,AVAILABLE}
22:07:11.107 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.201611041332 [100], contextID=default]}
22:07:11.108 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.201611041332 [137], contextID=default]}
22:07:11.108 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.201611041332 [138], contextID=default]}
22:07:11.108 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@14870c1}
22:07:11.109 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.201611041332 [186], contextID=default]}
22:07:11.109 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.classic_0.9.0.201611041332 [187], contextID=default]}
22:07:11.110 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.201611041332 [188], contextID=default]}
22:07:11.110 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.io.rest.docs_2.0.0.201611062131 [189], contextID=default]}
22:07:11.110 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.0.0.201611062131 [192], contextID=default]}
22:07:11.111 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.0.0.201611062131 [168], contextID=default]}
22:07:11.111 [DEBUG] [org.eclipse.jetty.server.Server     ] - RESPONSE /rest/sitemaps/_default/0000  200 handled=true
22:07:11.111 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@6e53d6{s=DISPATCHED i=true a=null} unhandle DISPATCHED
22:07:11.112 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - reset HttpParser{s=END,0 of -1}
22:07:11.112 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - END --> START
22:07:11.112 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=} handle exit, result COMPLETE
22:07:11.114 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,159/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,9/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] fill enter
22:07:11.114 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,10/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:11.115 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,161/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,11/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] filled 0 encrypted bytes
22:07:11.116 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,162/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,12/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] unwrap Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
22:07:11.118 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,163/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,13/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] fill exit
22:07:11.119 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,164/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,14/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] fill enter
22:07:11.119 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,15/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:11.120 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,166/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,16/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] filled 0 encrypted bytes
22:07:11.121 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,167/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,17/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] unwrap Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
22:07:11.122 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,168/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,18/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] fill exit
22:07:11.123 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@138a3c8[p=0,l=0,c=17408,r=0]={<<<>>>GET /rest/sitemap...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
22:07:11.124 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,169/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,19/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}]
22:07:11.125 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING-->FILLING_FILL_INTERESTED HttpConnection@12c6b19[FILLING_FILL_INTERESTED,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,170/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,20/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}]
22:07:11.126 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING_FILL_INTERESTED-->FILL_INTERESTED HttpConnection@12c6b19[FILL_INTERESTED,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,171/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,21/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}]
22:07:11.127 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILL_INTERESTED,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,R,-,0/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,22/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}]
22:07:11.128 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - IDLE-->FILL_INTERESTED SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILL_INTERESTED,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,R,-,1/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,24/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}]
22:07:11.129 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 0 -> 1 for SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,R,-,0/30000,SslConnection}{io=1,kio=0,kro=1}
22:07:11.129 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d2164a
22:07:11.129 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 0/1 selected
22:07:11.130 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d2164a
22:07:11.130 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 0 -> 1 on SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,R,-,2/30000,SslConnection}{io=1,kio=1,kro=1}
22:07:11.131 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
22:07:11.238 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop woken up from select, 1/1 selected
22:07:11.238 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 1 -> 0 on SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,R,-,110/30000,SslConnection}{io=1,kio=0,kro=1}
22:07:11.239 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Local interests updating 1 -> 0 for SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,R,-,111/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:11.239 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d2164a
22:07:11.240 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILL_INTERESTED-->FILLING SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILL_INTERESTED,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,R,-,114/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,112/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}]
22:07:11.241 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - onFillable enter DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,R,-,115/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,113/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:11.242 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILL_INTERESTED-->FILLING HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,115/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,114/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}]
22:07:11.243 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,117/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,115/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] onFillable HttpChannelState@6e53d6{s=IDLE i=true a=null}
22:07:11.244 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,118/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,116/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] fill enter
22:07:11.245 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 511 SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,117/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:11.246 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=511/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,120/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,1/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] filled 511 encrypted bytes
22:07:11.248 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=0/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,121/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,3/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] unwrap Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 511 bytesProduced = 482
22:07:11.249 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,122/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,4/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=39,c=false,a=IDLE,uri=}] fill exit
22:07:11.249 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@1ac887b[p=0,l=482,c=17408,r=482]={<<<GET /rest/sitemap...rwin/16.1.0\r\n\r\n>>>in/16.1.0\r\n\r\n\xE0\xBc\xB1\xF2...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
22:07:11.250 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> SPACE1
22:07:11.250 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE1 --> URI
22:07:11.250 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - URI --> SPACE2
22:07:11.250 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE2 --> REQUEST_VERSION
22:07:11.250 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - REQUEST_VERSION --> HEADER
22:07:11.251 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.251 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.251 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
22:07:11.251 [DEBUG] [g.eclipse.jetty.io.ssl.SslConnection] - onFillable exit DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,123/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,5/30000,SslConnection}{io=0,kio=0,kro=1}
22:07:11.251 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
22:07:11.252 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
22:07:11.252 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.252 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.252 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.252 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.252 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.253 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.253 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.253 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.253 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.254 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
22:07:11.254 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
22:07:11.254 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
22:07:11.254 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.254 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_NAME
22:07:11.255 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_NAME --> HEADER_VALUE
22:07:11.255 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_VALUE --> HEADER_IN_VALUE
22:07:11.255 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.255 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.255 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.255 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.256 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.256 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> HEADER_IN_VALUE
22:07:11.256 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER_IN_VALUE --> HEADER
22:07:11.256 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> END
22:07:11.257 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@d19aaf{r=40,c=false,a=IDLE,uri=/rest/sitemaps/_default/0000} messageComplete
22:07:11.257 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@15ca2 EOF
22:07:11.257 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING-->IDLE SslConnection@140f96f{NOT_HANDSHAKING,eio=-1/-1,di=-1} -> HttpConnection@12c6b19[FILLING,DecryptedEndPoint@47d536{/192.168.1.24:55097<->8443,Open,in,out,-,-,127/30000,HttpConnection}->SelectChannelEndPoint@c36456{/192.168.1.24:55097<->8443,Open,in,out,-,-,9/30000,SslConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=HEADER_IN_VALUE,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@d19aaf{r=40,c=false,a=IDLE,uri=/rest/sitemaps/_default/0000}]
22:07:11.257 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@d19aaf{r=40,c=false,a=IDLE,uri=/rest/sitemaps/_default/0000} handle enter
22:07:11.258 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@6e53d6{s=IDLE i=true a=null} handling IDLE
22:07:11.258 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@1d2164a
22:07:11.258 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@d19aaf{r=40,c=false,a=DISPATCHED,uri=/rest/sitemaps/_default/0000} action REQUEST_DISPATCH
22:07:11.259 [DEBUG] [org.eclipse.jetty.server.Server     ] - REQUEST GET /rest/sitemaps/_default/0000 on HttpChannelOverHttp@d19aaf{r=40,c=false,a=DISPATCHED,uri=/rest/sitemaps/_default/0000}
22:07:11.260 [DEBUG] [ax.web.service.spi.model.ServerModel] - Matching [/rest/sitemaps/_default/0000]...
22:07:11.260 [DEBUG] [ax.web.service.spi.model.ServerModel] - Path [/rest/sitemaps/_default/0000] matched to {pattern=/rest/.*,model=ServletModel{id=org.ops4j.pax.web.service.spi.model.ServletModel-2,name=org.ops4j.pax.web.service.spi.model.ServletModel-2,urlPatterns=[/rest/*],alias=/rest,servlet=com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge@1efe36d,initParams={},context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-1,name=,httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default],contextParams={},virtualHosts={},connectors={}}}}
22:07:11.260 [DEBUG] [.jetty.server.handler.ContextHandler] - scope null||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]}
22:07:11.261 [DEBUG] [.jetty.server.handler.ContextHandler] - context=||/rest/sitemaps/_default/0000 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]}
22:07:11.261 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Selector loop waiting on select
22:07:11.261 [DEBUG] [org.eclipse.jetty.server.session    ] - sessionManager=org.ops4j.pax.web.service.jetty.internal.LateInvalidatingHashSessionManager@1a5ce14
22:07:11.261 [DEBUG] [org.eclipse.jetty.server.session    ] - session=null
22:07:11.262 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - servlet |/rest|/sitemaps/_default/0000 -> org.ops4j.pax.web.service.spi.model.ServletModel-2@378be0fa==com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge,-1,true
22:07:11.262 [DEBUG] [ce.jetty.internal.HttpServiceContext] - Handling request for [/rest/sitemaps/_default/0000] using http context [DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [12], contextID=default]]
22:07:11.262 [DEBUG] [y.internal.HttpServiceServletHandler] - handling request org.ops4j.pax.web.service.jetty.internal.HttpServiceRequestWrapper@fee5d4, org.ops4j.pax.web.service.jetty.internal.HttpServiceResponseWrapper@1d0961
22:07:11.263 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - chain=null
22:07:12.534 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@dd0653{/192.168.1.9:60519<->8080,Open,in,out,-,-,30000/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
22:07:12.534 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@dd0653{/192.168.1.9:60519<->8080,Open,in,out,-,-,30001/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout expired
22:07:12.535 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - ignored: WriteFlusher@aca643{IDLE} java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
22:07:12.535 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SelectChannelEndPoint@dd0653{/192.168.1.9:60519<->8080,Open,in,out,-,-,30002/30000,HttpConnection}{io=0,kio=0,kro=1}
22:07:14.488 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
22:07:19.729 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@17b31db{/192.168.1.9:60535<->8080,Open,in,out,-,-,30000/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
22:07:19.730 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@17b31db{/192.168.1.9:60535<->8080,Open,in,out,-,-,30001/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout expired
22:07:19.730 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - ignored: WriteFlusher@14d7529{IDLE} java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
22:07:19.731 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SelectChannelEndPoint@17b31db{/192.168.1.9:60535<->8080,Open,in,out,-,-,30003/30000,HttpConnection}{io=0,kio=0,kro=1}
22:07:20.626 [DEBUG] [io.socket.engineio.client.Socket    ] - writing ping packet - expecting pong within 60000ms
22:07:20.626 [DEBUG] [io.socket.engineio.client.Socket    ] - flushing 1 packets in socket
22:07:20.669 [DEBUG] [io.socket.engineio.client.Socket    ] - socket received: type 'pong', data 'null'
22:07:21.383 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
22:07:24.489 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped

Repeated again and again
Log at startup would be of any interest ?
There is some progress though: NEW CONNECTION when starting OH2!!!

mysgw: Starting gateway...
mysgw: Protocol version - 2.0.1-beta
mysgw: MCO:BGN:INIT GW,CP=RNNG---,VER=2.0.1-beta
mysgw: TSF:LRT:OK
mysgw: TSM:INIT
mysgw: TSM:INIT:TSP OK
mysgw: TSM:INIT:GW MODE
mysgw: TSM:READY
mysgw: Listening for connections on 0.0.0.0:5003
mysgw: MCO:REG:NOT NEEDED
mysgw: MCO:BGN:STP
mysgw: MCO:BGN:INIT OK,ID=0,PAR=0,DIS=0,REG=1
mysgw: TSF:MSG:READ,1-1-0,s=255,c=3,t=26,pt=1,l=1,sg=0:2
mysgw: TSF:MSG:SEND,0-0-1-1,s=255,c=3,t=27,pt=1,l=1,sg=0,ft=0,st=OK:1
mysgw: TSF:MSG:READ,1-1-0,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
mysgw: TSF:MSG:SEND,0-0-1-1,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
mysgw: TSF:MSG:READ,1-1-0,s=255,c=0,t=17,pt=0,l=5,sg=0:2.0.0
mysgw: TSF:MSG:READ,1-1-0,s=255,c=3,t=6,pt=1,l=1,sg=0:0
mysgw: TSF:MSG:READ,1-1-0,s=255,c=3,t=11,pt=0,l=22,sg=0:TemperatureAndHumidity
mysgw: TSF:MSG:READ,1-1-0,s=255,c=3,t=12,pt=0,l=3,sg=0:1.1
mysgw: TSF:MSG:READ,1-1-0,s=0,c=0,t=7,pt=0,l=0,sg=0:
mysgw: TSF:MSG:READ,1-1-0,s=1,c=0,t=6,pt=0,l=0,sg=0:
mysgw: TSF:MSG:READ,1-1-0,s=255,c=3,t=26,pt=1,l=1,sg=0:2
mysgw: TSF:MSG:SEND,0-0-1-1,s=255,c=3,t=27,pt=1,l=1,sg=0,ft=0,st=OK:1
mysgw: TSF:MSG:READ,1-1-0,s=1,c=1,t=0,pt=7,l=5,sg=0:19.9
mysgw: TSF:MSG:READ,1-1-0,s=0,c=1,t=1,pt=7,l=5,sg=0:61.2
mysgw: New connection from 127.0.0.1
mysgw: Client 0 connected
mysgw: TSF:MSG:READ,1-1-0,s=0,c=1,t=1,pt=7,l=5,sg=0:61.3

Thank you so much for your time

TimO

@ben999 had a chat @Jic right now who has exactly the same problem.

There is still something wrong!
I'll keep searching!

undee

@TimO Can you say anything regarding the autoupdate=false option yet? It would be useful to separate the UI user action from the status displayed by the UI. Rollershutters for example can show the percentage of how much the shutters are down. This conflicts with the autoupdate=true behaviour which sets the value to 0 as soon as the UP button is pushed.

Jic

@TimO I have reviewed all my steps, and seems that I had not updated correctly the binding.
So later update Openhab2 to latest snapshot, the latest org.openhab.binding.mysensors-2.0.0-SNAPSHOT.jar now it working right.

0_1479854234589_Selección_003.png

thank you very much

ben999

@TimO
Will do as @Jic said and will start fresh tonight (europe) with latest OH2 and all on a fresh SD Card
There might be old files and bugs on this really messed up install...
Thanks again for your time and effort

TimO

@Jic I'm glad it worked out finally, thank you for your feedback!

@ben999 Please do so and ensure you install the latest snapshot of OH2.

At least I think we found the guilty one:

"The methods ThingHandler.bridgeHandlerInitialized() and ThingHandler.bridgeHandlerDisposed() are removed. This breaks the API."
PR LINK

The most annoying part is: I don't see a way to keep up backward compatibility with the current testing release (beta4).

TimO

@undee I'm not able to find a hint, that it is already implemented in OH2, do you have more information for me?

Defining:

Switch light01  "light01"       { autoupdate=false, channel="mysensors:light:gateway:light01:status" }

Returns:

[.e.s.m.i.i.GenericItemProvider:385  ] - Couldn't find ItemFactory for item 'channel' of type 'false'

Does not look like OH2 already knows what it means.

undee

@TimO The MQTT binding might be helpful. It is possible to implement the following behaviour with MQTT when autoupdate is set to false:

When you touch a switch, the defined message is published to an MQTT topic, but the button status remains unchanged. Then, for example, the device processes the message and publishes a status message which then causes the update to the visible status of the button.

The same can be implemented with shutters. When you push the button to move the shutters up, with autoupdate=true the icon is immediately set to reflect 0%. With autoupdate=false, you can show the current position by updating the position while it is in motion.

I can't do this with the MySensors binding yet because pushing a button always updates the status automatically.

ben999

@TimO
you deserve that one
All working fine, no trouble
Very clean OH2 log file
Happy man i am!
Thanks again for time, effort and availability
Please let me know if i can help in any way

pi@raspberrypi:/usr/share/openhab2 $ ./start.sh
Launching the openHAB runtime...

                          __  _____    ____      
  ____  ____  ___  ____  / / / /   |  / __ )     
 / __ \/ __ \/ _ \/ __ \/ /_/ / /| | / __  | 
/ /_/ / /_/ /  __/ / / / __  / ___ |/ /_/ /      
\____/ .___/\___/_/ /_/_/ /_/_/  |_/_____/     
    /_/                        2.0.0-SNAPSHOT
                               Build #609   

Hit '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
Hit '<ctrl-d>' or type 'system:shutdown' or 'logout' to shutdown openHAB.

openhab> log:set DEBUG org.openhab.binding.mysensors
openhab> log:tail
21:42:00.387 [DEBUG] [org.openhab.binding.mysensors       ] - BundleEvent STARTING - org.openhab.binding.mysensors
21:42:00.403 [DEBUG] [org.openhab.binding.mysensors       ] - BundleEvent STARTED - org.openhab.binding.mysensors
21:42:00.523 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.mysensors.internal.factory.MySensorsHandlerFactory, component.id=0, service.id=106, service.bundleid=10, service.scope=bundle} - org.openhab.binding.mysensors
21:42:14.666 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.things'
21:42:14.994 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'mysensors:bridge-eth:gateway' has been added.                                                                                   
21:42:15.002 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'mysensors:humidity:gateway:bathHum01' has been added.                                                                           
21:42:15.006 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'mysensors:temperature:gateway:bathTemp01' has been added.                                                                       
21:42:15.433 [DEBUG] [org.openhab.binding.mysensors       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=230, service.bundleid=10, service.scope=singleton} - org.openhab.binding.mysensors
21:42:15.451 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-eth:gateway' changed from UNINITIALIZED to INITIALIZING
21:42:15.453 [DEBUG] [ernal.handler.MySensorsBridgeHandler] - Initialization of the MySensors bridge
21:42:15.464 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:gateway:bathHum01' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
21:42:15.474 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:bathTemp01' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)                         
21:42:15.507 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Set skip check on startup to: false
21:42:15.508 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Enabling connection watchdog
21:42:15.517 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Connecting to IP bridge [127.0.0.1:5003]
21:42:15.532 [DEBUG] [ternal.factory.MySensorsCacheFactory] - Cache file: given_ids.cached exist.
21:42:15.534 [DEBUG] [ternal.factory.MySensorsCacheFactory] - Cache (given_ids) content: [1]
21:42:15.540 [DEBUG] [ernal.handler.MySensorsBridgeHandler] - Initialization of the MySensors bridge DONE!
21:42:15.541 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;14;Gateway startup complete.
21:42:15.548 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;14;Gateway startup complete.
21:42:15.552 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'mysensors_humidity_gateway_bathHum01_hum' has been added.
21:42:15.554 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;0;0;18;2.0.1-beta
21:42:15.556 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'mysensors_humidity_gateway_bathHum01_hum-mysensors:humidity:gateway:bathHum01:hum' has been added.
21:42:15.555 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;0;0;18;2.0.1-beta
21:42:15.559 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'mysensors_humidity_gateway_bathHum01_lastupdate' has been added.
21:42:15.562 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'mysensors_humidity_gateway_bathHum01_lastupdate-mysensors:humidity:gateway:bathHum01:lastupdate' has been added.                 
21:42:15.565 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'mysensors_temperature_gateway_bathTemp01_lastupdate' has been added.                                                             
21:42:15.569 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'mysensors_temperature_gateway_bathTemp01_lastupdate-mysensors:temperature:gateway:bathTemp01:lastupdate' has been added.         
21:42:15.571 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'mysensors_temperature_gateway_bathTemp01_temp' has been added.                                                                   
21:42:15.573 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'mysensors_temperature_gateway_bathTemp01_temp-mysensors:temperature:gateway:bathTemp01:temp' has been added.                     
21:42:15.729 [DEBUG] [rs.internal.protocol.MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
21:42:15.743 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;2;2.0.1-beta
21:42:15.744 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Good,Gateway is up and running! (Ver:2.0.1-beta)
21:42:15.745 [DEBUG] [rs.internal.protocol.MySensorsReader] - 0;255;3;0;2;2.0.1-beta
21:42:15.749 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-eth:gateway' changed from INITIALIZING to ONLINE
21:42:15.759 [INFO ] [al.protocol.ip.MySensorsIpConnection] - Successfully connected to MySensors Bridge.
21:42:15.761 [WARN ] [al.protocol.ip.MySensorsIpConnection] - Network Sanity Checker thread disabled from bridge configuration
21:42:15.788 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 1, chiledId: 1, revertState: false
21:42:15.789 [DEBUG] [ternal.handler.MySensorsThingHandler] - Event listener for node 1-1 not registered yet, registering...
21:42:15.789 [DEBUG] [ternal.handler.MySensorsThingHandler] - Configuration: node 1, chiledId: 0, revertState: false
21:42:15.790 [DEBUG] [ternal.handler.MySensorsThingHandler] - Event listener for node 1-0 not registered yet, registering...
21:42:15.794 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:bathTemp01' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
21:42:15.796 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:gateway:bathHum01' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
21:42:15.797 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:bathTemp01' changed from INITIALIZING to ONLINE
21:42:15.799 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:gateway:bathHum01' changed from INITIALIZING to ONLINE
21:42:17.115 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
21:42:17.453 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
21:42:17.949 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
21:42:18.125 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
21:42:25.762 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:42:35.763 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:42:45.765 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:42:55.766 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:43:05.768 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:43:13.988 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;0;1;0;1;62.5
21:43:14.005 [DEBUG] [ternal.handler.MySensorsThingHandler] - Setting last update for node 1 to 2016-11-23T21:43:13.995+0000
21:43:14.010 [DEBUG] [ternal.handler.MySensorsThingHandler] - Setting last update for node 1 to 2016-11-23T21:43:14.006+0000
21:43:14.016 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;0;1;0;1;62.5
21:43:14.022 [INFO ] [marthome.event.ItemStateChangedEvent] - mysensors_temperature_gateway_bathTemp01_lastupdate changed from NULL to 2016-11-23T21:43:13.995+0000
21:43:14.037 [INFO ] [marthome.event.ItemStateChangedEvent] - mysensors_humidity_gateway_bathHum01_lastupdate changed from NULL to 2016-11-23T21:43:14.006+0000
21:43:14.040 [INFO ] [marthome.event.ItemStateChangedEvent] - mysensors_humidity_gateway_bathHum01_hum changed from NULL to 62.5
21:43:15.769 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:43:25.771 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:43:35.772 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:43:45.775 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:43:55.778 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:44:05.779 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:44:15.780 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:44:20.330 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;1;1;0;0;18.9
21:44:20.340 [DEBUG] [ternal.handler.MySensorsThingHandler] - Setting last update for node 1 to 2016-11-23T21:44:20.333+0000
21:44:20.348 [DEBUG] [ternal.handler.MySensorsThingHandler] - Setting last update for node 1 to 2016-11-23T21:44:20.342+0000
21:44:20.349 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;1;1;0;0;18.9
21:44:20.352 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;0;1;0;1;62.0
21:44:20.362 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;0;1;0;1;62.0
21:44:20.364 [INFO ] [marthome.event.ItemStateChangedEvent] - mysensors_temperature_gateway_bathTemp01_lastupdate changed from 2016-11-23T21:43:13.995+0000 to 2016-11-23T21:44:20.333+0000
21:44:20.370 [INFO ] [marthome.event.ItemStateChangedEvent] - mysensors_temperature_gateway_bathTemp01_temp changed from NULL to 18.9
21:44:20.381 [INFO ] [marthome.event.ItemStateChangedEvent] - mysensors_humidity_gateway_bathHum01_lastupdate changed from 2016-11-23T21:43:14.006+0000 to 2016-11-23T21:44:20.342+0000
21:44:20.387 [INFO ] [marthome.event.ItemStateChangedEvent] - mysensors_humidity_gateway_bathHum01_hum changed from 62.5 to 62.0
21:44:25.783 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:44:35.785 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:44:45.786 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:44:55.788 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:45:05.789 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
21:45:15.792 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped

TimO

@ben999 Thank you for your kind words and for your patience!

I'm glad it is working now. As it is quiet for a day now, I suppose the problem is solved.

Jic

@TimO thanks to you. My Sensor seems working right since a week.

But I have noticed a beahaviour that I think it's anomal.
I have a Door Sensor, their lastupdate attribute upate their value almost each 10 minuts approximately. I think it should be updated when the state of the tripped value changes, or not?

Also, if the tripped value change quickly, the lastupdate attribute not change.

I'm triying that the lastupdate value is the last time the door was open or close, but I don't find the way to do that. Is this a bug? I have reviewed my skecht and I don't see any posible error in it.

Thanks in advance

TimO

@Jic Do you have a corresponding log for me?

My last update value only updates if a update is received. If I don't get an update for hours the last update variable won't change.

Maybe you receive a not tripped from the motion sensor? That will update the last update variable.

Jic

@TimO right now, I have only one Door sensor.
my logs are

2016-12-01 23:02:43.047 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-12-01 23:02:53.049 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-12-01 23:02:53.909 [DEBUG] [rs.internal.protocol.MySensorsReader] - 10;1;1;0;16;1
2016-12-01 23:02:53.923 [DEBUG] [ternal.handler.MySensorsThingHandler] - Setting last update for node 10 to 2016-12-01T23:02:53.913+0100
2016-12-01 23:02:53.990 [DEBUG] [rs.internal.protocol.MySensorsReader] - 10;255;3;0;22;100788
2016-12-01 23:03:03.051 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-12-01 23:03:13.053 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-12-01 23:07:03.111 [DEBUG] [col.serial.MySensorsSerialConnection] - Bridge is connected, connection skipped
2016-12-01 23:07:05.190 [DEBUG] [rs.internal.protocol.MySensorsReader] - 10;255;3;0;21;0
2016-12-01 23:07:05.203 [DEBUG] [ternal.handler.MySensorsThingHandler] - Setting last update for node 10 to 2016-12-01T23:07:05.193+0100

==> events.log <==
2016-12-01 23:07:05.229 [ItemStateChangedEvent     ] - mysensors_door_gateway_Door_10_1_lastupdate changed from 2016-12-01T23:02:53.913+0100 to 2016-12-01T23:07:05.193+0100
2016-12-01 23:07:05.264 [ItemStateChangedEvent     ] - Cancela01time changed from 2016-12-01T23:02:53.913+0100 to 2016-12-01T23:07:05.193+0100

You can see last event is at 23:07, however in the following snapshot the time is 11:17

0_1480631760477_Selección_004.png

No more events, but the lastupdate change

Jic

@TimO ok, I have discovered that my "tail" command doesn't work rigth, sorry

My logs are

2016-12-01 23:02:53.990 [DEBUG] [rs.internal.protocol.MySensorsReader] - 10;255;3;0;22;100788
2016-12-01 23:07:05.190 [DEBUG] [rs.internal.protocol.MySensorsReader] - 10;255;3;0;21;0
2016-12-01 23:17:05.248 [DEBUG] [rs.internal.protocol.MySensorsReader] - 10;255;3;0;21;0
2016-12-01 23:27:05.326 [DEBUG] [rs.internal.protocol.MySensorsReader] - 10;255;3;0;21;0
2016-12-01 23:37:05.409 [DEBUG] [rs.internal.protocol.MySensorsReader] - 10;255;3;0;21;0
2016-12-01 23:47:05.486 [DEBUG] [rs.internal.protocol.MySensorsReader] - 10;255;3;0;21;0
2016-12-01 23:57:05.562 [DEBUG] [rs.internal.protocol.MySensorsReader] - 10;255;3;0;21;0
2016-12-02 00:07:05.639 [DEBUG] [rs.internal.protocol.MySensorsReader] - 10;255;3;0;21;0

I don't understand why am I reciving this message?

TimO

@Jic According to the serial API this is a I_DISCOVER_RESPONSE, but why is it sent? This seeems to update the lastUpdate channel.

I see it this way: "lastUpdate" is the last time the node has sent something, so everything is working as expected.

Jic

@TimO

Thanks. I don't know why is it sending a I_DISCOVER_RESPONSE message. Any Idea?

openHAB 2.0 binding

Suggested Topics

Boxes and Enclosures
Enclosures / 3D Printing • • PITP2

openHAB 2.2 binding
OpenHAB • • TimO

MQTT losing messages...
OpenHAB • • ben999

openHAB 2.5 binding and V_VARx
OpenHAB • • syntacrsc

OH3 - MySensors Binding
OpenHAB • • Peter Loeffler

OH3, RPi3, GPIO-NRF24 gateway. MySensors binding (ETH or MQTT?)
OpenHAB • • perIpI

10
Online

11.4k
Users

11.1k
Topics

112.7k
Posts

openHAB 2.0 binding

Suggested Topics

Boxes and Enclosures Enclosures / 3D Printing • • PITP2

openHAB 2.2 binding OpenHAB • • TimO

MQTT losing messages... OpenHAB • • ben999

openHAB 2.5 binding and V_VARx OpenHAB • • syntacrsc

OH3 - MySensors Binding OpenHAB • • Peter Loeffler

OH3, RPi3, GPIO-NRF24 gateway. MySensors binding (ETH or MQTT?) OpenHAB • • perIpI

10Online

11.4kUsers

11.1kTopics

112.7kPosts

Boxes and Enclosures
Enclosures / 3D Printing • • PITP2

openHAB 2.2 binding
OpenHAB • • TimO

MQTT losing messages...
OpenHAB • • ben999

openHAB 2.5 binding and V_VARx
OpenHAB • • syntacrsc

OH3 - MySensors Binding
OpenHAB • • Peter Loeffler

OH3, RPi3, GPIO-NRF24 gateway. MySensors binding (ETH or MQTT?)
OpenHAB • • perIpI

10
Online

11.4k
Users

11.1k
Topics

112.7k
Posts