Open RolandRosenfeld opened 2 years ago
This issue has been mentioned on openHAB Community. There might be relevant details there:
https://community.openhab.org/t/homematic-hm-cc-vg-1-heating-groups-broken-in-oh-3-2/131296/6
I have got an installation with 5 heating groups on a Raspberrymatic system (CCU3 like system) with no problems. As far as I remember, this part of the binding code has not been changed between OH 3.1.1 and 3.2.0.
I suspect some sort of timing issue. Maybe there are too many requests at the same time for the CCU2 and it does no longer answer to the requests. Can you try to define the Bridge and the group devices in Main UI? I would like to find out if the problem occurs because the processing order of text files is different.
It would also help if you could create a log file with the OH 3.1.1 installation. Then we could compare both logs.
I temporarily enabled DEBUG logging for homematic and restarted OpenHAB. You can find the startup log at https://www.spinnaker.de/tmp/homematic-311.log I also suspect some kind of timing issue, that was introduced with 3.2, especially since calbackRegTimeout was introduced with 3.2. In addition to this the RpcClient init looks much more complicated now (Sorry, I'm not very familiar with Java) and uses a scheduler with hardcoded delays (INITIAL_CALLBACK_REG_DELAY and CALLBACK_REG_DELAY) now where a simple sendMessage without any timing definitions was used before... But whom do I tell this, according to the git logs, you know the binding much better than me...
I tried to use the Main UI in the following way: I removed the Things from the homematic things file (keeping only the Bridge entry) and upgraded to 3.2.0-1. The heating groups appeared in the inbox, but trying to use them resulted in the same errors as before.
I think it would be necessary to install the bridge in Main UI, too. Because as far as I can see in the logs the requests causing the problems appear during the bridge initialization.
I also suspect some kind of timing issue, that was introduced with 3.2, especially since calbackRegTimeout was introduced with 3.2. In addition to this the RpcClient init looks much more complicated now (Sorry, I'm not very familiar with Java) and uses a scheduler with hardcoded delays (INITIAL_CALLBACK_REG_DELAY and CALLBACK_REG_DELAY) now where a simple sendMessage without any timing definitions was used before...
You are right, the coding is quite ugly but necessary because the HmIP devices behave not very well if a reconnect is necessary. But I don't think that this code really causes the problem because the first sendMessage for the callback registration should will be successful if the CCU is already up and runnung.
I think it would be necessary to install the bridge in Main UI, too. Because as far as I can see in the logs the requests causing the problems appear during the bridge initialization.
To say the truth, I tried this by removing the homematic.things file and uninstalling/installing the homematic binding first, but nothing happened (no autodiscovery of the the CCU bridge). What's the correct way to install the bridge via Main UI? Can I actively trigger this or enter the CCU hostname or do have to be patient until OH scans all my networks (one LAN, one WAN and multiple VLANs for different WLANs) and finds an IP with ports that behave like a CCU? Maybe I also have to remove services/homematic.cfg? Sorry, but for me all this Main UI web configuration is voodoo...
Maybe I also have to remove services/homematic.cfg? What did you configure here?
Normally the CCU is automatically discovered after the binding has been installed or OH has been restarted. You can start a scan manually as follows:
Okay, "Scan" does not find any CCU (okay, that's because my firewall blocks UDP 43439). But adding it manually (by entering the hostname) finds the CCU. After this the inbox lists several devices, but the heating groups are missing. In openhab.log I read:
2022-01-22 22:30:04.543 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=CCU,type=CCU2,firmware=2.61.7,address=LEQ0090686,rf=true,wired=false,hmip=true,cuxd=false,group=true]
2022-01-22 22:30:16.335 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'homematic:HM-LC-Sw1PBU-FM:7d991ab0dd:MEQ0484589' to inbox.
[...]
2022-01-22 22:30:25.246 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'homematic:HmIP-RCV-50:7d991ab0dd:HmIP-RCV-1' to inbox.
2022-01-22 22:30:26.010 [WARN ] [ommunicator.AbstractHomematicGateway] - Can't load device with address 'INT0000008' from gateway '7d991ab0dd': java.util.concurrent.ExecutionException: org.eclipse.jetty.io.EofException
2022-01-22 22:30:26.065 [WARN ] [ommunicator.AbstractHomematicGateway] - Can't load device with address 'INT0000009' from gateway '7d991ab0dd': java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1dc4e4ed::SocketChannelEndPoint@57eef8af{l=/192.168.42.2:40442,r=homematic.sail.spinnaker.de/192.168.42.28:9292,ISHUT,fill=-,flush=-,to=3/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@1dc4e4ed(l:/192.168.42.2:40442 <-> r:homematic.sail.spinnaker.de/192.168.42.28:9292,closed=false)=>HttpChannelOverHTTP@738d4e9e(exchange=HttpExchange@6fc05a3f{req=HttpRequest[POST /groups HTTP/1.1]@551928a6[TERMINATED/null] res=HttpResponse[null 0 null]@7592992a[PENDING/null]})[send=HttpSenderOverHTTP@6c72d0b8(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18e6eab{s=START}],recv=HttpReceiverOverHTTP@1dce3a24(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
2022-01-22 22:30:26.095 [WARN ] [ommunicator.AbstractHomematicGateway] - Can't load device with address 'INT0000003' from gateway '7d991ab0dd': java.util.concurrent.ExecutionException: org.eclipse.jetty.io.EofException
2022-01-22 22:30:26.122 [WARN ] [ommunicator.AbstractHomematicGateway] - Can't load device with address 'INT0000005' from gateway '7d991ab0dd': java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@7c74bb7e::SocketChannelEndPoint@6795358{l=/192.168.42.2:40446,r=homematic.sail.spinnaker.de/192.168.42.28:9292,ISHUT,fill=-,flush=-,to=0/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@7c74bb7e(l:/192.168.42.2:40446 <-> r:homematic.sail.spinnaker.de/192.168.42.28:9292,closed=false)=>HttpChannelOverHTTP@74708e0a(exchange=HttpExchange@188385ba{req=HttpRequest[POST /groups HTTP/1.1]@41f5729f[TERMINATED/null] res=HttpResponse[null 0 null]@d5a0a6a[PENDING/null]})[send=HttpSenderOverHTTP@7daad515(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@7980314f{s=START}],recv=HttpReceiverOverHTTP@130bd56a(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
2022-01-22 22:30:26.150 [WARN ] [ommunicator.AbstractHomematicGateway] - Can't load device with address 'INT0000006' from gateway '7d991ab0dd': java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@4edf943b::SocketChannelEndPoint@6576e288{l=/192.168.42.2:40448,r=homematic.sail.spinnaker.de/192.168.42.28:9292,ISHUT,fill=-,flush=W,to=1/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@4edf943b(l:/192.168.42.2:40448 <-> r:homematic.sail.spinnaker.de/192.168.42.28:9292,closed=false)=>HttpChannelOverHTTP@1d04bd20(exchange=HttpExchange@50698b6f{req=HttpRequest[POST /groups HTTP/1.1]@62a5b315[TERMINATED/null] res=HttpResponse[null 0 null]@30956f6b[PENDING/null]})[send=HttpSenderOverHTTP@8c029e4(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@14eee960{s=START}],recv=HttpReceiverOverHTTP@5b1ccdf3(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
2022-01-22 22:30:26.195 [WARN ] [ommunicator.AbstractHomematicGateway] - Can't load device with address 'INT0000010' from gateway '7d991ab0dd': java.util.concurrent.ExecutionException: org.eclipse.jetty.io.EofException
2022-01-22 22:30:26.224 [WARN ] [ommunicator.AbstractHomematicGateway] - Can't load device with address 'INT0000002' from gateway '7d991ab0dd': java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@40e90fcc::SocketChannelEndPoint@496f913c{l=/192.168.42.2:40452,r=homematic.sail.spinnaker.de/192.168.42.28:9292,ISHUT,fill=-,flush=W,to=1/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@40e90fcc(l:/192.168.42.2:40452 <-> r:homematic.sail.spinnaker.de/192.168.42.28:9292,closed=false)=>HttpChannelOverHTTP@2aa9c498(exchange=HttpExchange@17e7f76b{req=HttpRequest[POST /groups HTTP/1.1]@1ff81d34[TERMINATED/null] res=HttpResponse[null 0 null]@2aab8986[PENDING/null]})[send=HttpSenderOverHTTP@4ec2154f(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@6636ef53{s=START}],recv=HttpReceiverOverHTTP@39f85f1c(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
2022-01-22 22:30:26.274 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'homematic:GATEWAY-EXTRAS-7D991AB0DD:7d991ab0dd:GWE00000000' to inbox.
In services/homematic.cfg I have the following lines active:
host=homematic.sail.spinnaker.de
callback.host=192.168.42.2
(192.168.42.2 is the LAN IP of my OH server. homematic.sail.spinnaker.de points to 192.168.42.28)
I have compared the log files and I can see that the request sequence and the state changes of the bridge differ between both releases.
You can now try the following:
bufferSize
If both does not help it would be necessary to produce more log output:
log:set DEBUG org.eclipse.jetty.client
(this will produce quite a lot output)I increased bufferSize to 20480 (the default should be 2048, if I got this right). I tried to reduce the log size to a minimum (not including too much output of other bindings), which isn't trivial. During my tests I removed all rules files and all things file (except homematic.things) and with this setup all things started up correctly... But now I found a way to extract the requested data:
java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1eeb5b17::SocketChannelEndPoint@1e6ed61d{l=/192.168.42.2:40412,r=homematic.sail.spinnaker.de/192.168.42.28:9292,ISHUT,fill=-,flush=-,to=1/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@1eeb5b17(l:/192.168.42.2:40412 <-> r:homematic.sail.spinnaker.de/192.168.42.28:9292,closed=false)=>HttpChannelOverHTTP@6bea5546(exchange=HttpExchange@1261bc5b{req=HttpRequest[POST /groups HTTP/1.1]@56167ee3[TERMINATED/null] res=HttpResponse[null 0 null]@3ea08402[PENDING/null]})[send=HttpSenderOverHTTP@7d9b6f5(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c54131{s=START}],recv=HttpReceiverOverHTTP@7d41c5ac(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
in the Main UI, before they got online (the above was copy&pasted from a later test, you won't find the tags in the log)
Only INT0000008 reproducible shows a configuration error (instead of a communication error) and stays with this
Device with address 'INT0000008' not found on gateway 'ccu'
in the Main UI and with the message
2022-01-23 14:11:38.250 [WARN ] [ommunicator.AbstractHomematicGateway] - Can't load device with address 'INT0000008' from gateway 'ccu': java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@7cd232a3::SocketChannelEndPoint@998425a{l=/192.168.42.2:38964,r=homematic.sail.spinnaker.de/192.168.42.28:9292,ISHUT,fill=-,flush=-,to=9/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@7cd232a3(l:/192.168.42.2:38964 <-> r:homematic.sail.spinnaker.de/192.168.42.28:9292,closed=false)=>HttpChannelOverHTTP@164466ed(exchange=HttpExchange@5cad3424{req=HttpRequest[POST /groups HTTP/1.1]@e5579df[PENDING/null] res=HttpResponse[null 0 null]@533bf9e8[PENDING/null]})[send=HttpSenderOverHTTP@55c9b50b(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@3863c23b{s=START}],recv=HttpReceiverOverHTTP@7322ddff(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
in the logfile.
Thanks for your support. Will need some time to analyze the logs, but it really seems that there maybe are too many parallel requests for the CCU. The problem seems to be either caused by the newer Jetty version or a modification in the send method. Because I never heard of any problems with a CCU3 it seems that the CCU3 can handle these requests better.
I could see the same behavior like RolandRosenfeld described in the first Post when i upgraded to openHAB 3.3.0.M5 yesterday. I also noticed that my CCU2 throw me an Error on the Webinterface that Parts of the OS Crashed and then i need to powercycle the CCU2. My Homematic Setup is similar to Rolands, i got several HM-CC-RT-DN grouped with HM-TC-IT-WM-W-EU and the virtual Device Groups couldn´t be discovered. As a workaround i increased the buffersize of the Homeatic Binding and disabled the "HmIP-RCV-50 HmIP-RCV-1" Item , the Virtual Devices could be discovered and were usable but after a restart they seem not working again as the initialization is throwing an error:
07:58:56.469 [WARN ] [communicator.AbstractHomematicGateway] - Can't load device with address 'INT0000008' from gateway '74629296ca': java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@389df690::SocketChannelEndPoint@3d7cbb8e{l=/192.168.1.5:52064,r=/192.168.1.50:9292,ISHUT,fill=-,flush=-,to=0/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@389df690(l:/192.168.1.5:52064 <-> r:/192.168.1.50:9292,closed=false)=>HttpChannelOverHTTP@54965b2b(exchange=HttpExchange@6b2df82f{req=HttpRequest[POST /groups HTTP/1.1]@3cd3aaac[TERMINATED/null] res=HttpResponse[null 0 null]@64abd673[PENDING/null]})[send=HttpSenderOverHTTP@20296ce(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@6eaea21{s=START}],recv=HttpReceiverOverHTTP@274db69a(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]] 07:58:56.503 [WARN ] [communicator.AbstractHomematicGateway] - Can't load device with address 'INT0000009' from gateway '74629296ca': java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1d6ff44e::SocketChannelEndPoint@b4db5cb{l=/192.168.1.5:52066,r=/192.168.1.50:9292,ISHUT,fill=-,flush=-,to=0/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@1d6ff44e(l:/192.168.1.5:52066 <-> r:/192.168.1.50:9292,closed=false)=>HttpChannelOverHTTP@5a27ed61(exchange=HttpExchange@101469d9{req=HttpRequest[POST /groups HTTP/1.1]@723b2211[TERMINATED/null] res=HttpResponse[null 0 null]@14be3270[PENDING/null]})[send=HttpSenderOverHTTP@71178963(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@42fe7c39{s=START}],recv=HttpReceiverOverHTTP@69fee5dd(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]] 07:58:56.535 [WARN ] [communicator.AbstractHomematicGateway] - Can't load device with address 'INT0000005' from gateway '74629296ca': java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@cb66720::SocketChannelEndPoint@4127bb44{l=/192.168.1.5:52068,r=/192.168.1.50:9292,ISHUT,fill=-,flush=-,to=0/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@cb66720(l:/192.168.1.5:52068 <-> r:/192.168.1.50:9292,closed=false)=>HttpChannelOverHTTP@700918ed(exchange=HttpExchange@6ec7cb3c{req=HttpRequest[POST /groups HTTP/1.1]@51772ea3[TERMINATED/null] res=HttpResponse[null 0 null]@2df64252[PENDING/null]})[send=HttpSenderOverHTTP@1500f971(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@45ce4ec6{s=START}],recv=HttpReceiverOverHTTP@2d2472ea(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]] 07:58:56.568 [WARN ] [communicator.AbstractHomematicGateway] - Can't load device with address 'INT0000006' from gateway '74629296ca': java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@325f51ce::SocketChannelEndPoint@2086ed85{l=/192.168.1.5:52070,r=/192.168.1.50:9292,ISHUT,fill=-,flush=-,to=1/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@325f51ce(l:/192.168.1.5:52070 <-> r:/192.168.1.50:9292,closed=false)=>HttpChannelOverHTTP@17092f2d(exchange=HttpExchange@1934bc04{req=HttpRequest[POST /groups HTTP/1.1]@512d5fcd[TERMINATED/null] res=HttpResponse[null 0 null]@46d07aa8[PENDING/null]})[send=HttpSenderOverHTTP@18fe4518(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@24160e9f{s=START}],recv=HttpReceiverOverHTTP@1ffeeee7(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]] 07:58:56.584 [INFO ] [ing.homematic.internal.misc.MiscUtils] - Datapoint name '${sysVarAlarmZone1}' contains invalid characters, new Datapoint name '__sysVarAlarmZone1_' 07:58:56.585 [INFO ] [ing.homematic.internal.misc.MiscUtils] - Datapoint name '${sysVarPresence}' contains invalid characters, new Datapoint name '__sysVarPresence_' 07:58:56.585 [DEBUG] [communicator.AbstractHomematicGateway] - Loaded 0 gateway variable(s)
Same here. After updating to 3.3.0 the heating groups are broken and other items won't be updated. I have rolled back to 3.2.0 for now.
Same with 3.4.0.M5:
13:37:20.147 [WARN ] [communicator.AbstractHomematicGateway] - Can't load device with address 'INT0000002' from gateway 'ccu': java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@69bc5938::SocketChannelEndPoint@5415be2d{l=/192.168.178.63:53982,r=/192.168.178.44:9292,ISHUT,fill=-,flush=-,to=0/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@69bc5938(l:/192.168.178.63:53982 <-> r:/192.168.178.44:9292,closed=false)=>HttpChannelOverHTTP@53d365f6(exchange=HttpExchange@3d153b45{req=HttpRequest[POST /groups HTTP/1.1]@366bd046[TERMINATED/null] res=HttpResponse[null 0 null]@4ff6e470[PENDING/null]})[send=HttpSenderOverHTTP@7c2c4ad(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@13990803{s=START}],recv=HttpReceiverOverHTTP@7b1803d6(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
I am not sure whether this problem is really caused by the binding's code or by the Jetty version used. I have got several heating groups and non of them causes a problem like this (I am running version 3.3.0 since months). But I have got a CCU3 (Raspberrymatic)
@sehroriginell Do you have a CCU2 or a CCU3?
@MHerbst, this error occurs on the CCU2, which I was suspecting after some searching.
Today I upgraded my system to a CCU3. Everything is working fine now.
So if you are using a CCU2, you won't be able to upgrade openHAB to 3.2 or 3.3.
Unfortunately, even with the CCU3 the error occurs after a few days of uptime.
As you can see in the graphs, there have been no updates from any of the groups (all lines but the yellow one, which is not a group item but a sensor).
After resetting everything at around midnight, the groups have died again. In the console, it says: "OFFLINE (CONFIGURATION_ERROR): Device with address 'INT0000001' not found on gateway 'ccu'."
Hi,
I had no issues with the groups with 3.4.2 on my raspberry pi (bases on the openhabian image) and my CCU2. In the last days I am trying to switch to a docker setup on unraid and can report the same issue: 3.1.0 is working 3.4.2 is finding the groups but I get the "not found on gateway" error. All other items are working fine. I also tried the 4.0 snapshot from today. With this I can't even find the groups.
Edit: Found a workaround:
Restart you CCU (wait until complete) then restart openhab (or in my case the docker container) (in that order). Then the groups start to work again for me.
I will monitor if the groups will still be up after a few days.
Edit2: Workaround does work only sometimes
Welp, after a week of observation: It works only sometimes. Sometimes none of the groups work, sometimes only a few work, sometimes all of them are working
To determine the cause, it might be usefull to look at what was changed. From what i understand the issue/regression was introduced by 3.2 So here is a list of all PR's that where applied to the homematic binding for 3.2 Maybe there is some lead to this issue.
note it would also be worthwhile to check if 4.1.x has the same problem.
This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.
Expected Behavior
Heating groups (HM-CC-VG1) devices should just work, especially for SET_TEMPERATURE. For this it's required that the things for these virtual devices are online.
Current Behavior
Currently all HM-CC-VG-1 (INT0000*) things are offline with OH 3.2.0-1.
In events.log I see messages like:
In openhab.log on startup I see warnings (linebreaks manually added) like:
Possible Solution
The problem occurred on upgrade from 3.1.1 to 3.2.0. As a workaround downgrading OpenHAB (including the homematic binding) to 3.1.1 solves the problem for me.
Steps to Reproduce (for Bugs)
I run OH 3.2.0-1 with text file configuration. The homematic bridge and things are configured as
I defined items as
With this I observe the above mentioned errors and in the Main UI the heating group things show up as "OFFLINE".
Context
If you use heating groups (combining HM-TC-IT-WM-W-EU and HM-CC-RT-DN), you have to send all updates to the group (HM-CC-VG1), since the group overwrites changes, that are sent directly to HM-TC-IT-WM-W-EU or HM-CC-RT-DN. This means, that this issue breaks all changes.
I reported the problem at https://community.openhab.org/t/homematic-hm-cc-vg-1-heating-groups-broken-in-oh-3-2/131296 before and there seems to be at least one other user affected by the same problem. I generated a debug log, which is available at https://www.spinnaker.de/tmp/homematic.log
Your Environment