teichsta
commented
9 years ago @kgoderis could you please have a look at this one? Thanks, Thomas E.-E.
Open gersilex opened 9 years ago
teichsta
commented
9 years ago @kgoderis could you please have a look at this one? Thanks, Thomas E.-E.
kgoderis
commented
9 years ago @gersilex Do Windows machine happen to have some kind of sleep mode where they still accept network connections in the background? I don't have a Windows PC (sorry, Mac only shop here), so it is a bit hard for me to replicate. Based on the code I can only state that somehow the binding tries to connect to the Windows machine, and that the underlying Java NIO library seem to indicate that the connection can be successfully set up (which it then does with a finishconnect()). If you are fluent with the Eclipse IDE maybe you can try to run it step by step through the debugger and see what is happening here?
gersilex
commented
9 years ago Hey @kgoderis . Unfortunately, I have absolutely no experience with Eclipse. I could at least provide some tcp dumps. Openhab is also running on a headless machine, which makes debugging with the eclipse IDE even harder.
Windows computers do not accept connections if they are in Standby. This is a full S5 Sleep State (Everything powered off, except RAM)
Tomtibo
commented
9 years ago Hi @gersilex . I had a similar problem trying to control a TCP to IR device (gc100). The device was probably sending a "keep connection alive" command that OH do not respond to. And after a certain amount of time not responding, the device block the connection. I solve this by adding a rule sending a null command to keep alive the connection. In my case, sending command once by hours does the tricks! Not sure if it's a bug, or an item have to be setup to respond to the "keep connection alive"...
anthonygillet
commented
7 years ago I am also seeing this exact behavior with OH2 b4 on RPi3 using TCP binding 1.9.0.b4. I am connecting the TCP binding to an HTD GW-SL1, which is an IP to RS232 controller for an HTD whole-house audio system. Probably much like the one @Tomtibo describes. So this does not seem to be related only to Windows machines sleeping.
Has there been any progress on the investigation? Can I provide any logs to assist?
In the meantime I will try @Tomtibo 's solution.
9037568
commented
7 years ago Those interested in this issue may wish to try out the jar that may be a fix for #3163 to see if it also fixes this issue. Please see 3163 for the link. ( @gersilex, @Tomtibo, @anthonygillet )
anthonygillet
commented
7 years ago I just installed your jar in my OH2 system. It's working now, I'll let it run for a few days and I'll report back.
anthonygillet
commented
7 years ago Unfortunately using this new jar I can still reproduce the issue. Everything was fine for a few days, but when I rebooted some of my network equipment, the loop begins as before:
2017-01-26 12:21:56.923 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /10.42.0.168:10006 is now connected
2017-01-26 12:21:57.930 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /10.42.0.168:10006 is now connected
2017-01-26 12:21:58.939 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /10.42.0.168:10006 is now connectedThe binding was non-functional at this point. Other bindings recovered from the network issues (insteonplm, harmony, etc). I don't have any other equipment to test with, but I wonder if you could simply reproduce this issue by connecting to a TCP server and then unplugging that server's ethernet connection.
I'm using OH2 build 743. I installed the binding by first editing my addons.cfg to remove "tcp1", then dropping the jar in /usr/share/openhab/addons.
Is there any way to verify that my system is using the right addon? Do you need any other logs of the issue, e.g. TCP binding set to TRACE?
9037568
commented
7 years ago @anthonygillet if you could provide a DEBUG log, that would be great. I don't see any TRACE output in the TCP binding at present.
anthonygillet
commented
7 years ago Unfortunately there is not much log printed at the time of the incident. I can reproduce this consistently now by the following steps:
Here is the relevant log, this is just after I plugged the device back in and I tried sending a command:
2017-02-03 09:53:17.802 [INFO ] [ipse.smarthome.model.script.SPEAKERS] - Living Room Speakers received command: [22] Current State: [22] Device State: [0]
2017-02-03 09:53:17.821 [INFO ] [ipse.smarthome.model.script.SPEAKERS] - Sending command to device: [22]
2017-02-03 09:53:17.831 [DEBUG] [ing.tcp.protocol.internal.TCPBinding] - transformed response is 'W_??'
2017-02-03 09:53:17.937 [INFO ] [ipse.smarthome.model.script.SPEAKERS] - Living Room Speakers received command: [22] Current State: [22] Device State: [22]
2017-02-03 09:53:17.950 [INFO ] [ipse.smarthome.model.script.SPEAKERS] - Sending command to device: [22]
2017-02-03 09:53:17.959 [DEBUG] [ing.tcp.protocol.internal.TCPBinding] - transformed response is 'W_??'
2017-02-03 09:53:18.213 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Picked WriteBufferElement [Channel=Channel [item=living_room_speakers_device, command=1, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=/10.42.0.116:37502::/10.42.0.168:10006, host=10.42.0.168, port=10006], buffer=W_??, isblocking=false] from the queue
2017-02-03 09:53:18.214 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Sending W_?? for the outbound channel /10.42.0.116:37502->/10.42.0.168:10006
2017-02-03 09:53:19.217 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /10.42.0.168:10006 is now connected
2017-02-03 09:53:20.230 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /10.42.0.168:10006 is now connected
2017-02-03 09:53:21.238 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /10.42.0.168:10006 is now connected
2017-02-03 09:53:22.245 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /10.42.0.168:10006 is now connected
...Here is my TCP binding config:
# all parameters can be applied to both the TCP and UDP binding unless
# specified otherwise
# Port to listen for incoming connections
#port=25001
# Cron-like string to reconnect remote ends, e.g for unstable connection or remote ends
#reconnectcron=0 0 0 * * ?
# Interval between reconnection attempts when recovering from a communication error,
# in seconds
retryinterval=5
# Queue data whilst recovering from a connection problem (TCP only)
#queue=true
# Maximum buffer size whilst reading incoming data
buffersize=2048
# Share connections within the Item binding configurations
itemsharedconnections=true
# Share connections between Item binding configurations
bindingsharedconnections=true
# Share connections between inbound and outbound connections
directionssharedconnections=false
# Allow masks in ip:port addressing, e.g. 192.168.0.1:* etc
#addressmask=true
# Pre-amble that will be put in front of data being sent
#preamble=
# Post-amble that will be appended to data being sent
#postamble=\r\n
# Perform all write/read (send/receive) operations in a blocking mode, e.g. the binding
# will wait for a reply from the remote end after data has been sent
#blocking=false
# timeout, in milliseconds, to wait for a reply when initiating a blocking write/read
# operation
#timeout=3000
# Update the status of Items using the response received from the remote end (if the
# remote end sends replies to commands)
updatewithresponse=false
# Timeout - or 'refresh interval', in milliseconds, of the worker thread
refreshinterval=1000
# Timeout, in milliseconds, to wait when "Selecting" IO channels ready for communication
#selecttimeout=1000
# Used character set
charset=ISO-8859-1And here is how my items are defined. I have seven items linked to this TCP device, and I control virtual devices that send commands to the actual device so I can decide what to send it exactly via rules.
Group:Dimmer:OR(ON,OFF) all_speakers "All Speakers" ["Lighting"]
Group:Dimmer:OR(ON,OFF) downstairs_speakers "Downstairs Speakers" ["Lighting"]
Group:Dimmer:OR(ON,OFF) upstairs_speakers "Upstairs Speakers" ["Lighting"]
Switch speaker_input_kitchen "Kitchen Music" <signal> ["Switchable"] {tcp=">[ON:10.42.0.168:10006:'MAP(bluetooth_input.map)']"}
Switch speaker_input_bedroom "Bedroom Music" <signal> ["Switchable"] {tcp=">[ON:10.42.0.168:10006:'MAP(bedroom_input.map)']"}
Dimmer kitchen_speakers "Kitchen Speakers" <soundvolume> (all_speakers,downstairs_speakers) ["Lighting"]
Dimmer kitchen_speakers_device "Kitchen Speakers Actual Device" {tcp=">[10.42.0.168:10006:'MAP(kitchen_speakers.map)']"}
Dimmer living_room_speakers "Living Room Speakers" <soundvolume> (all_speakers,downstairs_speakers) ["Lighting"]
Dimmer living_room_speakers_device "Living Room Speakers Actual Device" {tcp=">[10.42.0.168:10006:'MAP(living_room_speakers.map)']"}
Dimmer master_bath_speakers "Master Bath Speakers" <soundvolume> (all_speakers,upstairs_speakers) ["Lighting"]
Dimmer master_bath_speakers_device "Master Bath Actual Device" {tcp=">[10.42.0.168:10006:'MAP(master_bath_speakers.map)']"}
Dimmer bedroom_speakers "Bedroom Speakers" <soundvolume> (all_speakers,upstairs_speakers) ["Lighting"]
Dimmer bedroom_speakers_device "Bedroom Speakers Actual Device" {tcp=">[10.42.0.168:10006:'MAP(bedroom_speakers.map)']"}
Dimmer deck_speakers "Deck Speakers" <soundvolume> ["Lighting"]
Dimmer deck_speakers_device "Deck Speakers Actual Device" {tcp=">[10.42.0.168:10006:'MAP(deck_speakers.map)']"}Everything appears fine upon startup:
2017-02-03 10:03:50.899 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The cron job to reset connections will be set to the default value of 0 0 0 * * ?
2017-02-03 10:03:50.901 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The setting to queue write operation until a channel gets connected will be set to the default value of true
2017-02-03 10:03:50.902 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The port to listen for incoming connections will be set to the default value of 0
2017-02-03 10:03:50.903 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The setting to use address masks for incoming connections will be set to the default value of true
2017-02-03 10:03:50.928 [INFO ] [ing.tcp.protocol.internal.TCPBinding] - The maximum time out for blocking write operations will be set to the default value of 3000
2017-02-03 10:03:50.929 [INFO ] [b.core.service.AbstractActiveService] - TCP Refresh Service has been started
2017-02-03 10:03:50.929 [INFO ] [ing.tcp.protocol.internal.TCPBinding] - The blocking nature of read/write operations will be set to the default value of false
2017-02-03 10:03:50.931 [INFO ] [ing.tcp.protocol.internal.TCPBinding] - The preamble for all write operations will be set to the default value of ""
2017-02-03 10:03:50.932 [INFO ] [ing.tcp.protocol.internal.TCPBinding] - The postamble for all write operations will be set to the default value of ""
2017-02-03 10:03:50.940 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Setting up the outbound channel Channel [item=speaker_input_kitchen, command=ON, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=, host=10.42.0.168, port=10006]
2017-02-03 10:03:50.944 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Connecting the channel Channel [item=speaker_input_kitchen, command=ON, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=, host=10.42.0.168, port=10006]
2017-02-03 10:03:50.946 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Setting up the outbound assigned channel Channel [item=kitchen_speakers_device, command=0, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=::/10.42.0.168:10006, host=10.42.0.168, port=10006]
2017-02-03 10:03:50.948 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Setting up the outbound assigned channel Channel [item=bedroom_speakers_device, command=3, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=::/10.42.0.168:10006, host=10.42.0.168, port=10006]
2017-02-03 10:03:50.950 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Setting up the outbound assigned channel Channel [item=deck_speakers_device, command=4, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=::/10.42.0.168:10006, host=10.42.0.168, port=10006]
2017-02-03 10:03:50.952 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Setting up the outbound assigned channel Channel [item=speaker_input_bedroom, command=ON, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=::/10.42.0.168:10006, host=10.42.0.168, port=10006]
2017-02-03 10:03:50.953 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Setting up the outbound assigned channel Channel [item=master_bath_speakers_device, command=2, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=::/10.42.0.168:10006, host=10.42.0.168, port=10006]
2017-02-03 10:03:50.955 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Setting up the outbound assigned channel Channel [item=living_room_speakers_device, command=1, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=::/10.42.0.168:10006, host=10.42.0.168, port=10006]
2017-02-03 10:03:50.957 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /10.42.0.168:10006 is now connectedAnd everything appears fine upon sending normal commands:
2017-02-03 10:05:43.671 [INFO ] [ipse.smarthome.model.script.SPEAKERS] - Living Room Speakers received command: [30] Current State: [30] Device State: [36]
2017-02-03 10:05:43.685 [INFO ] [ipse.smarthome.model.script.SPEAKERS] - Sending command to device: [30]
2017-02-03 10:05:43.693 [DEBUG] [ing.tcp.protocol.internal.TCPBinding] - transformed response is 'W_??'
2017-02-03 10:05:43.848 [INFO ] [ipse.smarthome.model.script.SPEAKERS] - Living Room Speakers received command: [30] Current State: [30] Device State: [30]
2017-02-03 10:05:43.855 [INFO ] [ipse.smarthome.model.script.SPEAKERS] - Sending command to device: [30]
2017-02-03 10:05:43.861 [DEBUG] [ing.tcp.protocol.internal.TCPBinding] - transformed response is 'W_??'
2017-02-03 10:05:44.395 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Picked WriteBufferElement [Channel=Channel [item=living_room_speakers_device, command=1, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=/10.42.0.116:38444::/10.42.0.168:10006, host=10.42.0.168, port=10006], buffer=W_??, isblocking=false] from the queue
2017-02-03 10:05:44.817 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Sending W_?? for the outbound channel /10.42.0.116:38444->/10.42.0.168:10006
2017-02-03 10:05:45.820 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '' with the file 'bluetooth_input.map' : Target value not found in map for ''
2017-02-03 10:05:45.821 [DEBUG] [ing.tcp.protocol.internal.TCPBinding] - transformed response is ''
2017-02-03 10:05:45.823 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input to match command ON on item speaker_input_kitchen
2017-02-03 10:05:45.825 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '' with the file 'kitchen_speakers.map' : Target value not found in map for ''
2017-02-03 10:05:45.826 [DEBUG] [ing.tcp.protocol.internal.TCPBinding] - transformed response is ''
2017-02-03 10:05:45.828 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input to match command 0 on item kitchen_speakers_device
2017-02-03 10:05:45.830 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '' with the file 'bedroom_speakers.map' : Target value not found in map for ''
2017-02-03 10:05:45.831 [DEBUG] [ing.tcp.protocol.internal.TCPBinding] - transformed response is ''
2017-02-03 10:05:45.834 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input to match command 3 on item bedroom_speakers_device
2017-02-03 10:05:45.837 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '' with the file 'deck_speakers.map' : Target value not found in map for ''
2017-02-03 10:05:45.838 [DEBUG] [ing.tcp.protocol.internal.TCPBinding] - transformed response is ''
2017-02-03 10:05:45.840 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input to match command 4 on item deck_speakers_device
2017-02-03 10:05:45.842 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '' with the file 'bedroom_input.map' : Target value not found in map for ''
2017-02-03 10:05:45.844 [DEBUG] [ing.tcp.protocol.internal.TCPBinding] - transformed response is ''
2017-02-03 10:05:45.845 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input to match command ON on item speaker_input_bedroom
2017-02-03 10:05:45.847 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '' with the file 'master_bath_speakers.map' : Target value not found in map for ''
2017-02-03 10:05:45.848 [DEBUG] [ing.tcp.protocol.internal.TCPBinding] - transformed response is ''
2017-02-03 10:05:45.850 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input to match command 2 on item master_bath_speakers_device
2017-02-03 10:05:45.852 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '' with the file 'living_room_speakers.map' : Target value not found in map for ''
2017-02-03 10:05:45.853 [DEBUG] [ing.tcp.protocol.internal.TCPBinding] - transformed response is ''
2017-02-03 10:05:45.855 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input to match command 1 on item living_room_speakers_device
2017-02-03 10:05:46.857 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Picked WriteBufferElement [Channel=Channel [item=living_room_speakers_device, command=1, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=/10.42.0.116:38444::/10.42.0.168:10006, host=10.42.0.168, port=10006], buffer=W_??, isblocking=false] from the queue
2017-02-03 10:05:46.859 [DEBUG] [ing.tcp.AbstractSocketChannelBinding] - Sending W_?? for the outbound channel /10.42.0.116:38444->/10.42.0.168:10006Let me know if you need more information.
lolorc
commented
7 years ago reproduced here as well with a openhab2 build from Jan 21st 2017
9037568
commented
7 years ago @anthonygillet it would be helpful if you could upload the actual openhab.log file. These snippets don't provide the line numbers.
pentti12
commented
7 years ago I'm having the same issue with my Marantz amplifier TCP binding. Just got the amplifier to power off by TCP packet. TCP binding seems to uninstall itself after daemon restart.
openhab.log
2017-04-21 18:05:51.061 [INFO ] [b.core.service.AbstractActiveService] - TCP Refresh Service has been shut down 2017-04-21 18:05:51.659 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet 2017-04-21 18:05:51.793 [ERROR] [org.quartz.core.JobRunShell ] - Job org.openhab.binding.tcp.protocol.internal.TCPBinding@42406af6.42406af6-Reconnect-1492797946786 threw an unhandled Exception: java.nio.channels.ClosedSelectorException at sun.nio.ch.EPollSelectorImpl.implRegister(EPollSelectorImpl.java:174)[:1.8.0_121] at sun.nio.ch.SelectorImpl.register(SelectorImpl.java:132)[:1.8.0_121] at java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:212)[:1.8.0_121] at java.nio.channels.SelectableChannel.register(SelectableChannel.java:280)[:1.8.0_121] at org.openhab.binding.tcp.AbstractSocketChannelBinding$ReconnectJob.execute(AbstractSocketChannelBinding.java:1150)[229:org.openhab.binding.tcp:1.10.0.201704100111] at org.quartz.core.JobRunShell.run(JobRunShell.java:202)[105:org.eclipse.smarthome.core.scheduler:0.9.0.201704011656] at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)[105:org.eclipse.smarthome.core.scheduler:0.9.0.201704011656] 2017-04-21 18:05:51.802 [ERROR] [org.quartz.core.ErrorLogger ] - Job (org.openhab.binding.tcp.protocol.internal.TCPBinding@42406af6.42406af6-Reconnect-1492797946786 threw an exception. org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: java.nio.channels.ClosedSelectorException] at org.quartz.core.JobRunShell.run(JobRunShell.java:213)[105:org.eclipse.smarthome.core.scheduler:0.9.0.201704011656] at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)[105:org.eclipse.smarthome.core.scheduler:0.9.0.201704011656] Caused by: java.nio.channels.ClosedSelectorException at sun.nio.ch.EPollSelectorImpl.implRegister(EPollSelectorImpl.java:174)[:1.8.0_121] at sun.nio.ch.SelectorImpl.register(SelectorImpl.java:132)[:1.8.0_121] at java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:212)[:1.8.0_121] at java.nio.channels.SelectableChannel.register(SelectableChannel.java:280)[:1.8.0_121] at org.openhab.binding.tcp.AbstractSocketChannelBinding$ReconnectJob.execute(AbstractSocketChannelBinding.java:1150)[229:org.openhab.binding.tcp:1.10.0.201704100111] at org.quartz.core.JobRunShell.run(JobRunShell.java:202)[105:org.eclipse.smarthome.core.scheduler:0.9.0.201704011656] ... 1 more 2017-04-21 18:05:52.916 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI 2017-04-21 18:05:52.944 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel 2017-04-21 18:05:52.963 [INFO ] [.dashboard.internal.DashboardService] - Stopped dashboard 2017-04-21 18:06:27.361 [INFO ] [ore.internal.i18n.LocaleProviderImpl] - Locale set to fi_FI 2017-04-21 18:06:40.041 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'marantz.items' 2017-04-21 18:06:54.210 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start 2017-04-21 18:06:56.365 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui 2017-04-21 18:06:57.685 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin 2017-04-21 18:06:58.100 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel 2017-04-21 18:06:58.414 [WARN ] [g.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.1.214 2017-04-21 18:06:59.202 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Listening for incoming connections on /0:0:0:0:0:0:0:0:24001 2017-04-21 18:06:59.210 [INFO ] [ing.tcp.protocol.internal.TCPBinding] - The preamble for all write operations will be set to the default value of "" 2017-04-21 18:06:59.224 [INFO ] [ing.tcp.protocol.internal.TCPBinding] - The postamble for all write operations will be set to the default value of "" 2017-04-21 18:06:59.225 [INFO ] [b.core.service.AbstractActiveService] - TCP Refresh Service has been started 2017-04-21 18:06:59.244 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Connecting the channel Channel [item=kitchen_speakers_device, command=0, direction=OUT, remote=/192.168.1.151:8080, buffer=, isBlocking=false, isReconnecting=false, channel=, host=192.168.1.151, port=8080] 2017-04-21 18:06:59.246 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Connecting the channel Channel [item=Marantz_ONOFF, command=ON, direction=OUT, remote=/192.168.1.151:8080, buffer=, isBlocking=false, isReconnecting=false, channel=, host=192.168.1.151, port=8080] 2017-04-21 18:06:59.250 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Connecting the channel Channel [item=MarantzON, command=ON, direction=OUT, remote=/192.168.1.151:8080, buffer=, isBlocking=false, isReconnecting=false, channel=, host=192.168.1.151, port=8080] 2017-04-21 18:06:59.253 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Connecting the channel Channel [item=speaker_input_bedroom, command=ON, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=, host=10.42.0.168, port=10006] 2017-04-21 18:06:59.269 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.151:8080 is now connected 2017-04-21 18:06:59.558 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.151:8080 is now connected 2017-04-21 18:06:59.876 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.151:8080 is now connected 2017-04-21 18:07:02.420 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:07:07.439 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:07:14.487 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:07:19.494 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:07:22.652 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:07:27.658 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:07:34.713 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:07:39.720 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:07:43.724 [ERROR] [org.openhab.binding.tcp ] - [org.openhab.binding.tcp.protocol.udp(156)] The deactivate method has thrown an exception java.lang.NullPointerException at org.openhab.binding.tcp.AbstractDatagramChannelBinding.deactivate(AbstractDatagramChannelBinding.java:731) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_121] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_121] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_121] at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_121] at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:302)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:294)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:343)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:152)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:813)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:787)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.DependencyManager.deactivateComponentManager(DependencyManager.java:2225)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.DependencyManager.access$500(DependencyManager.java:55)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:386)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:291)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1241)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1136)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.untrack(ServiceTracker.java:996)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1175)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)[32:org.apache.felix.scr:2.0.6] at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:222)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:908)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:873)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:139)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterService(AbstractComponentManager.java:950)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:805)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:787)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:579)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:706)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:523)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:452)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.Activator.access$300(Activator.java:54)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:306)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:290)[32:org.apache.felix.scr:2.0.6] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_121] at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121] at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:312)[32:org.apache.felix.scr:2.0.6] at org.apache.felix.utils.extender.AbstractExtender.bundleChanged(AbstractExtender.java:186)[32:org.apache.felix.scr:2.0.6] at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.Module.doStop(Module.java:624)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:419)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.apache.karaf.features.internal.service.FeaturesServiceImpl.stopBundle(FeaturesServiceImpl.java:1293)[8:org.apache.karaf.features.core:4.0.8] at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:612)[8:org.apache.karaf.features.core:4.0.8] at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1176)[8:org.apache.karaf.features.core:4.0.8] at org.apache.karaf.features.internal.service.FeaturesServiceImpl$1.call(FeaturesServiceImpl.java:1074)[8:org.apache.karaf.features.core:4.0.8] at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_121] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_121] at java.lang.Thread.run(Thread.java:745)[:1.8.0_121] 2017-04-21 18:07:43.763 [INFO ] [b.core.service.AbstractActiveService] - TCP Refresh Service has been shut down 2017-04-21 18:07:43.962 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-binding-tcp1' 2017-04-21 18:11:00.578 [INFO ] [thome.io.rest.core.item.ItemResource] - Received HTTP POST request at 'items/null' for the unknown item 'null'. 2017-04-21 18:11:40.947 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Listening for incoming connections on /0:0:0:0:0:0:0:0:24001 2017-04-21 18:11:40.949 [INFO ] [b.core.service.AbstractActiveService] - TCP Refresh Service has been started 2017-04-21 18:11:40.949 [INFO ] [ing.tcp.protocol.internal.TCPBinding] - The preamble for all write operations will be set to the default value of "" 2017-04-21 18:11:40.951 [INFO ] [ing.tcp.protocol.internal.TCPBinding] - The postamble for all write operations will be set to the default value of "" 2017-04-21 18:11:40.968 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Connecting the channel Channel [item=kitchen_speakers_device, command=0, direction=OUT, remote=/192.168.1.151:8080, buffer=, isBlocking=false, isReconnecting=false, channel=, host=192.168.1.151, port=8080] 2017-04-21 18:11:40.971 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Connecting the channel Channel [item=Marantz_ONOFF, command=ON, direction=OUT, remote=/192.168.1.151:8080, buffer=, isBlocking=false, isReconnecting=false, channel=, host=192.168.1.151, port=8080] 2017-04-21 18:11:40.975 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Connecting the channel Channel [item=MarantzON, command=ON, direction=OUT, remote=/192.168.1.151:8080, buffer=, isBlocking=false, isReconnecting=false, channel=, host=192.168.1.151, port=8080] 2017-04-21 18:11:40.988 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Connecting the channel Channel [item=speaker_input_bedroom, command=ON, direction=OUT, remote=/10.42.0.168:10006, buffer=, isBlocking=false, isReconnecting=false, channel=, host=10.42.0.168, port=10006] 2017-04-21 18:11:40.993 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.151:8080 is now connected 2017-04-21 18:11:41.032 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.151:8080 is now connected 2017-04-21 18:11:41.109 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.151:8080 is now connected 2017-04-21 18:11:41.382 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:11:46.392 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:12:17.545 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:12:22.557 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:12:23.593 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:12:28.603 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:12:28.632 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:12:33.643 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:12:33.671 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:12:38.717 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:12:55.365 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:2 ' with the file 'marantz.map' : Target value not found in map for '@PWR:2 ' 2017-04-21 18:12:55.375 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:2 to match command 0 on item kitchen_speakers_device 2017-04-21 18:12:55.381 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:2 ' with the file 'marantz.map' : Target value not found in map for '@PWR:2 ' 2017-04-21 18:12:55.386 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:2 to match command ON on item MarantzON 2017-04-21 18:12:55.392 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:2 ' with the file 'marantz.map' : Target value not found in map for '@PWR:2 ' 2017-04-21 18:12:55.398 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:2 to match command ON on item Marantz_ONOFF 2017-04-21 18:13:09.987 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:13:14.997 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:13:15.025 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:13:20.036 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:13:23.081 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:13:28.091 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:13:28.122 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:2 ' with the file 'marantz.map' : Target value not found in map for '@PWR:2 ' 2017-04-21 18:13:28.126 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:2 to match command 0 on item kitchen_speakers_device 2017-04-21 18:13:28.129 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:13:28.140 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:2 ' with the file 'marantz.map' : Target value not found in map for '@PWR:2 ' 2017-04-21 18:13:28.144 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:2 to match command ON on item MarantzON 2017-04-21 18:13:28.150 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:2 ' with the file 'marantz.map' : Target value not found in map for '@PWR:2 ' 2017-04-21 18:13:28.157 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:2 to match command ON on item Marantz_ONOFF 2017-04-21 18:13:33.138 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:13:33.191 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:13:35.468 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:1 ' with the file 'marantz.map' : Target value not found in map for '@PWR:1 ' 2017-04-21 18:13:35.475 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:1 to match command 0 on item kitchen_speakers_device 2017-04-21 18:13:35.480 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:1 ' with the file 'marantz.map' : Target value not found in map for '@PWR:1 ' 2017-04-21 18:13:35.484 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:1 to match command ON on item MarantzON 2017-04-21 18:13:35.490 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:1 ' with the file 'marantz.map' : Target value not found in map for '@PWR:1 ' 2017-04-21 18:13:35.495 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:1 to match command ON on item Marantz_ONOFF 2017-04-21 18:13:38.202 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:13:41.036 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:2 ' with the file 'marantz.map' : Target value not found in map for '@PWR:2 ' 2017-04-21 18:13:41.040 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:2 to match command 0 on item kitchen_speakers_device 2017-04-21 18:13:41.046 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:2 ' with the file 'marantz.map' : Target value not found in map for '@PWR:2 ' 2017-04-21 18:13:41.051 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:2 to match command ON on item MarantzON 2017-04-21 18:13:41.055 [WARN ] [rm.AbstractFileTransformationService] - Could not transform '@PWR:2 ' with the file 'marantz.map' : Target value not found in map for '@PWR:2 ' 2017-04-21 18:13:41.059 [WARN ] [ing.tcp.protocol.internal.TCPBinding] - Can not parse input @PWR:2 to match command ON on item Marantz_ONOFF 2017-04-21 18:13:45.340 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:13:50.350 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:13:53.396 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:13:58.412 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:14:05.482 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:14:10.493 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:14:13.544 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:14:18.553 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:14:18.580 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:14:23.590 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:14:23.621 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:14:28.634 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:14:28.912 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:14:33.922 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:14:33.953 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:14:38.964 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:14:38.991 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:14:44.000 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:14:44.030 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:14:49.041 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:14:49.069 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:14:54.078 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:15:01.149 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:15:06.156 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:15:21.262 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:15:26.277 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:15:26.306 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:15:31.314 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:15:31.345 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:15:36.354 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:15:43.428 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:15:48.438 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:16:16.822 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel 2017-04-21 18:16:16.982 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel 2017-04-21 18:16:19.662 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:16:19.899 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel 2017-04-21 18:16:20.029 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel 2017-04-21 18:16:24.669 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:16:25.703 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:16:30.711 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:16:33.758 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:16:38.769 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:16:38.799 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:16:43.807 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:16:46.851 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:16:51.861 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006 2017-04-21 18:16:54.908 [WARN ] [ing.tcp.AbstractSocketChannelBinding] - The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host 2017-04-21 18:16:59.916 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - Attempting to reconnect the channel for /10.42.0.168:10006
tbnobody
commented
6 years ago I am having the same problem. TCP connection works fine until I turn off (and on again) a ethernet relay module. I don't see any exception immediate within the log file but a lot of messages like:
2017-10-12 23:40:10.858 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:11.111 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:11.363 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:11.615 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:11.868 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:12.121 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:12.376 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:12.628 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:12.879 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:13.131 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:13.383 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:13.636 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:13.888 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connected
2017-10-12 23:40:14.140 [INFO ] [ing.tcp.AbstractSocketChannelBinding] - The channel for /192.168.1.245:5002 is now connectedWhen I restart OpenHAB I get the following exception (at shutdown):
23:48:19.472 [ERROR] [org.openhab.binding.tcp ] - [org.openhab.binding.tcp.protocol.tcp(166)] The deactivate method has thrown an exception
java.lang.NullPointerException
at org.openhab.binding.tcp.AbstractSocketChannelBinding.deactivate(AbstractSocketChannelBinding.java:727)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_144]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_144]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_144]
at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_144]
at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:302)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:294)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:343)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:152)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:813)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:787)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.DependencyManager.deactivateComponentManager(DependencyManager.java:2225)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.DependencyManager.access$500(DependencyManager.java:55)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:386)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:291)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1241)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1136)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.untrack(ServiceTracker.java:996)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1175)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)[31:org.apache.felix.scr:2.0.6]
at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:222)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:908)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:873)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:139)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterService(AbstractComponentManager.java:950)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:805)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:787)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:579)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:706)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:523)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:452)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator.access$300(Activator.java:54)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:306)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:290)[31:org.apache.felix.scr:2.0.6]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_144]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_144]
at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:312)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.utils.extender.AbstractExtender.bundleChanged(AbstractExtender.java:186)[31:org.apache.felix.scr:2.0.6]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.doStop(Module.java:624)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:1623)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1542)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:248)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:144)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.doStop(Module.java:626)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:186)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:159)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_144]
23:48:19.484 [ERROR] [org.openhab.binding.tcp ] - [org.openhab.binding.tcp.protocol.udp(168)] The deactivate method has thrown an exception
java.lang.NullPointerException
at org.openhab.binding.tcp.AbstractDatagramChannelBinding.deactivate(AbstractDatagramChannelBinding.java:731)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_144]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_144]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_144]
at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_144]
at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:302)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:294)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:343)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:152)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:813)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:787)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.DependencyManager.deactivateComponentManager(DependencyManager.java:2225)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.DependencyManager.access$500(DependencyManager.java:55)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:386)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:291)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1241)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1136)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.untrack(ServiceTracker.java:996)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1175)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)[31:org.apache.felix.scr:2.0.6]
at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:222)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:908)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:873)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:139)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterService(AbstractComponentManager.java:950)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:805)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:787)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:579)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:706)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:523)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:452)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator.access$300(Activator.java:54)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:306)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:290)[31:org.apache.felix.scr:2.0.6]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_144]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_144]
at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:312)[31:org.apache.felix.scr:2.0.6]
at org.apache.felix.utils.extender.AbstractExtender.bundleChanged(AbstractExtender.java:186)[31:org.apache.felix.scr:2.0.6]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.doStop(Module.java:624)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:1623)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1542)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:248)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:144)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.doStop(Module.java:626)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:186)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:159)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_144]
JCT250
commented
6 years ago I'm getting exactly the same issue as tbnobody after a period of time the logs will fill, the CPU usage will go to 100% and the system will freeze. Getting the same error message when restarting the service as well.
I have two TCP devices connected, one is a global cache IP2IR and the other is an eBay IP to RS232 converter. Only started to happen after upgrading to openhab2 from 1.8
JCT250
commented
6 years ago Not sure how useful this will be but rolled back to my 1.7.1 instance of openhab with the 1.7.1 TCP binding and can confirm that there are no issues here.
9037568
commented
6 years ago I can fix the null pointer exceptions reported by @tbnobody. Here's a test jar that does so.
I doubt that those are the cause of the original issue in this ticket, but if someone wants to verify this fix I'll submit a PR for them.
JCT250
commented
6 years ago @9037568 had been updating my IP addressing so spun up the openhab2 vm and gave that jar a go, can confirm that I'm no longer getting the error messages when starting / stopping the openhab2 service anymore using the test jar you provided.
pentti12
commented
6 years ago Good work. I will test this later when I have made back the running oh2 server.
JCT250
commented
6 years ago I think this needs to remain open. The null pointer issue is fixed but the original memory leak issue is still there
9037568
commented
6 years ago Indeed, as far as I'm aware, this is not fixed. However, the test bundle I linked above does contain some small improvements. I'd be curious to see if testing the original issue produces any difference in result.
ghostface
commented
6 years ago I have the same problem, sometimes a remote raspberry pi running hyperion daemon for controlling a led bar locks up and openhab will run into outofmemory issues due to some memory leak.
LuckyMallari
commented
6 years ago +1 I experience the same issue especially if your using hostname on TCP Binding.. Try using a hostname, then disable your DHCP. One hostname (DHCP lease expires and) cannot be resolved, of course it will fail, but memory usage goes up like crazy then finally:
Caused by: org.glassfish.jersey.server.ContainerException: java.lang.OutOfMemoryError: Java heap space
at org.glassfish.jersey.servlet.internal.ResponseWriter.rethrow(ResponseWriter.java:278) ~[?:?]
at org.glassfish.jersey.servlet.internal.ResponseWriter.failure(ResponseWriter.java:260) ~[?:?]
at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:509) ~[?:?]
at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:334) ~[?:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271) ~[?:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) ~[?:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:315) ~[?:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:297) ~[?:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:267) ~[?:?]
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) ~[?:?]
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) ~[?:?]
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) ~[?:?]
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) ~[?:?]
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) ~[?:?]
at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) ~[?:?]
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) ~[?:?]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[?:?]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) ~[?:?]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) ~[?:?]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284) ~[?:?]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) ~[?:?]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) ~[?:?]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) ~[?:?]
... 13 more
GoHoHa
commented
6 years ago Same problem here with OH2.3 at Xubuntu running the TCP binding "binding-tcp1 - 1.12.0.SNAPSHOT". Everything is running fine, but after the network is lost shortly the binding floods the log and never reconnects.
JCT250
commented
5 years ago Given this is still an issue, wondering what other people have been doing to work around it? I'd like to be able to upgrade to openhab 2.x but given the number of devices that I'm connecting to using the TCP binding that's not really an option until either there's a fix or workaround
e33b1711
commented
5 years ago Hi there,
i have a similar problem. I've got a telnet server running on a raspi, openhab connects via the tcp via binding over wifi to it. Sometimes it crashes after hours, sometimes after weaks. The same thing via ethernet to a server running on a ardunio works fine. It is the wifi, i guess. As soon as the connection dies, the tcp binding cant recover it and spams til java runs out of heap space. Unfortunately i am not into java. But i think i have found stable stettings: I edited my tcp.cfg: retryinterval=5 refreshinterval=1000 (rest is unedited) Now the binding can at least recover, when i restart the raspi (telnet server). Before it couldnt and started spamming.
arberg
commented
5 years ago I havn't found a stable solution with tcp binding. I've written about it here with all my files. It spams reconnects attempts 10.000 times/sec, after server tcp has been down overnight. Also binding directions don't work as they should, or I can't get the send to just send, and the receiver to just receive updates.
arberg
commented
5 years ago I also just noticed if I change the ip-port on the single item using tcp binding, it still spams log-entries for the old ip- 10.0.0.4. This fits with the idea that tcp-bindings probably has a schedule loop of old scheduled jobs, instead of scheduling for current config, and ensuring there is only one scheduled job
[WARN ] [ding.tcp.AbstractSocketChannelBinding] - Channel for /10.0.0.4:7000 is not reconnecting.
dotorg
commented
5 years ago arberg -- for what its worth, I agree with your readme changes. In fact, I think the very first thing it should say is "This binding is fundamentally broken, will cause your system to fail in non-obvious ways, should be removed from the repository entirely, but isn't, so just be aware."
I can't say how much time I would've saved over the last year with my setup if it had been obvious from the start that this binding doesn't work properly.
arberg
commented
5 years ago Yeah, I kindof agree, thanks for the feedback. I have wasted much time, that could have been spent much better implementing MQTT. If I get around to it, I'll implement MQTT in my home-environment, and then update documentation with relevant pointers that might make that a lot easier for others.
dotorg
commented
5 years ago For what its worth, I worked around the issues with the TCP binding by just using socat (which is implemented properly) to create a virtual serial port, and using the serial binding (which is implemented properly). It adds another layer of configuration, but its been reliable.
I basically followed this: https://community.openhab.org/t/forwarding-of-serial-and-usb-ports-over-the-network-to-openhab/46597
IMO, given that this binding has been broken for over three years, that should be the recommended way of doing TCP interactions in OH at this point.
arberg
commented
5 years ago Thank you for the info. Its good to have another alternative solution. I've tried it myself, but I have added the info to the documentation. Will you review my changes before I create a pull-request?
https://github.com/openhab/openhab1-addons/compare/master...arberg:patch-1
If you can edit my post, feel free to do so or send me your updated version of the addition, if any.
Best Alex
dotorg
commented
5 years ago I think that's probably fine. The specifics of how to set it up are pretty coupled to the particular install, so I don't think more detail will help.
My system has been completely stable since I switched to socat and the serial binding to replace the TCP binding, which is very nice after so long of having issues.
Hey there. I have the classy problem of openhab dying after some hours and could break it down to one addon:
Here, have a look at my config:
Reproduction
(Everything works fine and WILL stay fine here)
(repeats with every worker (refresh) cycle)
Open file descriptors rise to a non-critical value. Memory rises to the limits of Xmx Java Heap Space (but not to the system's limits) until it finally breaks:
By the way - the binding won't re-connect the tcp socket, even if I start 192.168.100 again. It just keeps spamming. Without the TCP Binding the system ran fine multiple days - although being some kind of useless, of course ;)
If I can provide you anything more, please tell me! Here are some graphs. From the logs you can see it broke at about 05:19 AM.
(timestamps from log and graphs may differ in timezone (was UTC instead of CEST)