TCP (UDB) Binding spams logs even though tcp-connection is active and working. It spams with the frequency set in reconnectcron once the tcp connection is active the first time since openhab restart
[WARN ] [ding.tcp.AbstractSocketChannelBinding] - Channel for /10.0.0.4:7000 is not reconnecting.
When the remote tcp-server is shutdown it immediately starts increasing its spam very quickly towards max cpu, which is for me is 10.000 reconnect attempts / sec
[INFO ] [ding.tcp.AbstractSocketChannelBinding] - The channel for /10.0.0.4:7000 is now connected
[WARN ] [ding.tcp.AbstractSocketChannelBinding] - Channel for /10.0.0.4:7000 is not reconnecting.
I suspect it tries to reconnect every 250 ms, and thinks it succeeds, yet fails, and then schedules yet another cron job, and so goes bananas.
I’m writing this because I have spent a fair amount of time trying to get TCP binding to work, and now I discover this is well documented in the issue list, yet not in the TCP binding wiki. I’ll post update there afterwards. I found many others having issues with tcp-binding here, but it looked like most got it to work.
As a side-note here’s a solution by JGluch that I suspect works to replace tcp with mtqq+python server: [SOLVED] Optoma beamer via RS232 over TCP/IP connector
During all my messing about, I misunderstood the direction, and forgot that “<[]” means openhab listens on port, and “>]” means openhab connects to remote server. So it makes no sence trying to receive on one, and send on the other. So ignore comments in code about that and just go with what worked for me, namely just one item binding with {tcp=">[10.0.0.4:7000:]"}
This is the GitHub issue I found:
I’m on OpenHAB 2.4 M5, TCP Binding 1.13.0-M5.
I’ve tried many different settings, I’ll post some of what I’ve done below, but I suspect the setup matters little, because its just a bug, but perhaps there’s a way around the bug. I’ve tried defaults with tcp.cfg params shared, and tried with all true, and all false.
Items file
// When tested below options, I had no receiving binding like tcp="<[]"
// Worked:
// String TCP_Lyngdorf "Lyngdorf TCP" (gHifi) [ "Hifi" ] { tcp=">[10.0.0.4:7000:'REGEX((.*))']" } // Input received from lyngdorf, eg 'TCP_Lyngdorf changed from !VOLDN to !VOL(-280)!'
// String TCP_Lyngdorf "Lyngdorf TCP" (gHifi) [ "Hifi" ] { tcp=">[10.0.0.4:7000:REGEX((.*))]" } // Input received from lyngdorf, eg 'TCP_Lyngdorf changed from !VOLDN to !VOL(-280)!'
// String TCP_Lyngdorf "Lyngdorf TCP" (gHifi) [ "Hifi" ] { tcp=">[10.0.0.4:7000:default]" } // Input received from lyngdorf
// String TCP_Lyngdorf "Lyngdorf TCP" (gHifi) [ "Hifi" ] { tcp=">[10.0.0.4:7000:]" } // Input received from lyngdorf
// String TCP_Lyngdorf "Lyngdorf TCP" (gHifi) [ "Hifi" ] { tcp=">[*:10.0.0.4:7000:]" } // Data sent to and input received from lyngdorf
// Didn't work:
// String TCP_Lyngdorf "Lyngdorf TCP" (gHifi) [ "Hifi" ] { tcp=">[10.0.0.4:7000:*]" } // input not received
// String TCP_Lyngdorf "Lyngdorf TCP" (gHifi) [ "Hifi" ] { tcp=">[:10.0.0.4:7000:]" } // data not sent
////////// > listed first
// String TCP_Lyngdorf "Lyngdorf TCP Send [%s]" (gHifi) [ "Hifi" ] { tcp=">[*:10.0.0.4:7000:],<[*:10.0.0.4:7000:]" }
// => There is no channel that services [itemName=TCP_Lyngdorf, command=!VOLDN]
// with directionssharedconnections=true
// I don't think it connected, nothing was sent
////////// < listed first
// String TCP_Lyngdorf "Lyngdorf TCP Send [%s]" (gHifi) [ "Hifi" ] { tcp="<[*:10.0.0.4:7000:],>[*:10.0.0.4:7000:]" }
// => Channel for /10.0.0.4:7000 is not reconnecting.
// with directionssharedconnections=true
// connects and sends data
// Lyngdorf wasn't sending data when this happened, I think. something weird. I dont Think it got data when I got it to work, not sure
/////
// String TCP_Lyngdorf_Receive "Lyngdorf TCP Rec [%s]" (gHifi) [ "Hifi" ] { tcp="<[*:10.0.0.4:7000:]" }
// String TCP_Lyngdorf "Lyngdorf TCP Send [%s]" (gHifi) [ "Hifi" ] { tcp=">[*:10.0.0.4:7000:]" }
// => Channel for /10.0.0.4:7000 is not reconnecting.
// with directionssharedconnections=true
// connects and sends data
////////// all sharing disables
// String TCP_Lyngdorf_Receive "Lyngdorf TCP Rec [%s]" (gHifi) [ "Hifi" ] { tcp="<[*:10.0.0.4:7000:]" }
// String TCP_Lyngdorf "Lyngdorf TCP [%s]" (gHifi) [ "Hifi" ] { tcp=">[*:10.0.0.4:7000:]" }
// with *share*=false
// port=0
// => The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host
// Strangely enough TCP_Lyngdorf_Receive gets no events, and TCP_Lyngdorf still receives data returned from tcp as seen
// in ItemStateChangedEvent but no update 'received update' is returned
// WHEN server tcp down, we get logs ' The channel for /10.0.0.4:7000 is now connected' and
// rapidly increasing spam in logs towards 7 pr ms starding tith 1/2 pr sec
/////////
String TCP_Lyngdorf_Receive "Lyngdorf TCP Rec [%s]" (gHifi) [ "Hifi" ] { tcp="<[*:10.0.0.4:7000:]" }
String TCP_Lyngdorf "Lyngdorf TCP [%s]" (gHifi) [ "Hifi" ] { tcp=">[*:10.0.0.4:7000:]" }
Switch Lyngdorf "Lyngdorf TDAI-2170" (gHifi) [ "Hifi" ]
Rollershutter LyngdorfVolumeSteps "Lyngdorf Volume [%d]" (gHifi) [ "Hifi" ]
Number LyngdorfVolumeNum "Lyngdorf Volume [%d]" (gHifi) [ "Hifi" ]
Switch LyngdorfSubscription "Lyngdorf TDAI-2170 Subscription" (gHifi) [ "Hifi" ]
Number LyngdorfInput "Lyngdorf Input [%d]" (gHifi)
String LyngdorfInputName "Lyngdorf Input [%s]" (gHifi)
Some of my rules
rule "Lyngdorf"
when
Item Lyngdorf received command or
Item LyngdorfVolumeSteps received command or
Item LyngdorfInput received command or
Item LyngdorfInputName received command
then
var c=transform("MAP", "lyngdorf_TDAI2170.map", receivedCommand.toString)
// logWarn("hifi.rules", "LyngdorfVolumeSteps send: "+receivedCommand+" => '"+ c+"'")
TCP_Lyngdorf.sendCommand(c)
end
////////// Receive item ///////////////////
rule "Lyngdorf TCP Received - Command"
when
Item TCP_Lyngdorf_Receive received command
then
logWarn("hifi.rules", "New received command: "+TCP_Lyngdorf_Receive.state)
end
rule "Lyngdorf TCP Received - Update"
when
Item TCP_Lyngdorf_Receive received update
then
logWarn("hifi.rules", "New received update: "+TCP_Lyngdorf_Receive.state)
end
rule "Lyngdorf TCP Received - changed"
when
Item TCP_Lyngdorf_Receive changed
then
logWarn("hifi.rules", "New changed update: "+TCP_Lyngdorf_Receive.state)
end
////////// ORG Send item ///////////////////
rule "Lyngdorf TCP - changed"
when
Item TCP_Lyngdorf changed
then
logWarn("hifi.rules", "Changed: "+TCP_Lyngdorf.state)
end
rule "Lyngdorf TCP - Command"
when
Item TCP_Lyngdorf received command
then
// TCP_Lyngdorf.sendCommand("!SUBSCRIBEVOL")
logWarn("hifi.rules", "Command: "+TCP_Lyngdorf.state)
end
// Below receives both commands and updates, but fortunately commands and status differ in values from Lyngdorf
rule "Lyngdorf TCP - Update"
when
Item TCP_Lyngdorf received update
then
if (TCP_Lyngdorf.state !== null) {
var fullState = TCP_Lyngdorf.state.toString()
var splitArray = fullState.split("\r\n")
for (String stateLine : splitArray) {
// logError("hifi.rules", "Update TCP_Lyngdorf line: '"+stateLine+"'")
if (stateLine.matches("!.*!")) {
// logInfo("hifi.rules", "Update - Matches !.*!: '"+stateLine+"'")
var value = transform("REGEX", ".*!VOL\\((-?\\d+)\\)!.*", stateLine)
if (value !== null) {
var valueInt = Integer.parseInt(value)
logInfo("hifi.rules", "Update Volume: "+stateLine+" => "+value+", int="+valueInt)
// LyngdorfVolumeSteps.postUpdate(new Percent(1-(-15-valueInt)/(15-70)))
LyngdorfVolumeNum.postUpdate(valueInt/10.0)
} else if ((value = transform("REGEX", "!SRC\\((\\d+)\\)!", stateLine)) !== null) { // !SRC(9) is data we send to Lyngdorf, !SRC(9)! is response state data
var valueInt=Integer.parseInt(value)
LyngdorfInput.postUpdate(valueInt)
LyngdorfInputName.postUpdate(transform("MAP", "lyngdorf_TDAI2170_status.map", value))
logInfo("hifi.rules", "Update Source: "+stateLine+" => "+valueInt)
} else if ((value = transform("REGEX", "!PWR\\((ON|OFF)\\)!", stateLine)) !== null) { // !SRC(9) is data we send to Lyngdorf, !SRC(9)! is response state data
if (value == "ON") {
Lyngdorf.postUpdate(ON)
} else {
Lyngdorf.postUpdate(OFF)
}
logInfo("hifi.rules", "Update PWR: "+stateLine+" => "+value)
} else {
logInfo("hifi.rules", "Update - No matching transform found: "+stateLine)
}
} else { // all commands sent to Lyngdorf end up here
// logInfo("hifi.rules", "Update - Not a status string from lyngdorf, no matching !.*!: '"+stateLine+"'")
}
}
}
end
my map (the out-going map) which works
ON=!ON
OFF=!OFF
UP=!VOLUP
DOWN=!VOLDN
SUBSCRIBE=!SUBSCRIBE
UNSUBSCRIBE=!UNSUBSCRIBE
SUBSCRIBEVOL=!SUBSCRIBEVOL
UNSUBSCRIBEVOL=!UNSUBSCRIBEVOL
Squeezebox=!SRC(2)
Tv=!SRC(3)
ChromecastAudio=!SRC(4)
Pc=!SRC(7)
UsbPc=!SRC(6)
ChromecastTv=!SRC(9)
1=!SRC(1)
2=!SRC(2)
3=!SRC(3)
4=!SRC(4)
5=!SRC(5)
6=!SRC(6)
7=!SRC(7)
8=!SRC(8)
9=!SRC(9)
10=!SRC(10)