Hello, I think I could catche the issue. I have copied all log files, paradox.log, openhab.log and events. log. I hope it would help. paradox_20190917.log (64.8 KB)
Hi,
thanks but kudos should go to @Jean_Henning and @jpbarraca who really managed to catch the protocol specifics. I just coded the binding in Java.
For the IP150 version Iām sure binding should work on 1.xx. I believe that Iāve read somewhere that Paradox moved solely to cloud in 4.x but Iām not 100% sure.
The cloud version will not work here unless they open an API to their cloud service and we code it using this API.
Also we figured that there are differences between EVO48, 192 and HD. HD is marked as supported because I expected the protocol to be the same but I see that during the initial logon phase there are issues with that.
Cheers,
K.
1 Like
Thanks for the log !
I think there is a synchronization issue and Iām creating too many reset requests.
I believe Iāve fixed it now but it needs to be tested again because I didnāt run into such issue on my system.
New jar is up on the download repo. Hope it works. 
Also Iāve moved some of the repeatable log information to TRACE level so you can now reduce your log level to DEBUG and you should be able to see there more meaningful and not so repeatable info. Watchout for āTIMEOUT! org.openhab.binding.paradoxalarm.internal.handlers.ParadoxIP150BridgeHandler@12c5762 received message for socket timeout.ā 
ok, thanks! I try it.
Startin was succeful. Binding works. Iāll let you know tomorrow about longer result.
Iāve tested the starting. Changes are very small.
Please make sure to reduce log level to DEBUG so we can filter out unnecessary deep-dive information.
Here is the latest one. It has stopped again around 8:40 in the morning. What is interesting, that all zones shows online status.
paradox_20190921.log (4.9 KB)
2019-09-21 23:33:13.985 [DEBUG] [l.communication.AbstractCommunicator] - Unable to receive package due to IO Exception. Request RamRequest [getType()=RAM, getRamBlockNumber()=10]. Exception=Read timed out
2019-09-21 23:33:20.614 [DEBUG] [l.communication.AbstractCommunicator] - Unable to receive package due to IO Exception. Request RamRequest [getType()=RAM, getRamBlockNumber()=12]. Exception=Read timed out
2019-09-21 23:33:25.488 [DEBUG] [l.communication.AbstractCommunicator] - Unable to receive package due to IO Exception. Request RamRequest [getType()=RAM, getRamBlockNumber()=14]. Exception=Read timed out
2019-09-21 23:33:29.488 [DEBUG] [l.communication.AbstractCommunicator] - Unable to receive package due to IO Exception. Request RamRequest [getType()=RAM, getRamBlockNumber()=15]. Exception=Read timed out
Hi,
I looked into the logs and there is some concurrency issue it seems. Problem is that I cannot identify that from the logs right now.
Good news is that now the socket timeout is correctly handled from the logs and weāre not firing multiple remediation tasks to the scheduled executor service.
Problem that I see now is that the scheduled repeatable task that refreshes the data runs in parallel with remediation and itās expected this task to be cancelled before that happens. Problem is this log entry though. Why it fails? Strangeā¦
Canceling schedule of java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@1740d80 is failed
Could you try the following two actions applied together without any new fixes:
- Restart your whole openhab / karaf.
- Change the log4j2.appender.paradox.layout.pattern to the following:
log4j2.appender.paradox.layout.pattern = %t %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
The %t will give me which thread is logging the event.
What is also very strange is the null pointer in openhab.log ā if logon lifecycle is properly executed the listener should be never null.
Please try the advised when you can and provide me again logs if it fails again.
Sorry for the overhead but the concurrency issues are harder to identify. 
Best regards,
K.
Hello, Many thanks for quick reply. I have a suspicion that it conficts with Milight binding. Next time I will provide full log and I wonāt remove other messages just it would be much longer. I will do the modification in the loggign set up. What do you mean under restart whole openhab/karaf? I use windows10 and I installed OH as a service. So I can restart the windows service what would men complete restart of openhab. When I change the binding I delete catch and tmp folders and Openhab recreate all bindings all rules everythingh from scretch.
Restarting the service is enough. Idea to make sure that the runtime state of Karaf is reset. Sometimes when you only overwrite the addon, some tasks continue to run in background in separate threads leading to NPEs. Thatās probably due to bad lifecycle management from my end and I will need to look into that soonā¦
You donāt have to delete anything from TMP for Paradox binding to work.
Of course I donāt expect you to reset the configuration you already have. Do not reset rules and everything from scratch.
Cheers,
K.
OK. Thanks. When binding is changed TMP and Catch folders are necessary to delete. This way we force OH to build up the structure again with the new binding. I have experienece that when I had just changed the jar files in the addon folder it was not enough. Openhab was operating from catch folder and everything remained unchanged. I have made a small rule that the binding reset the connection in every each hour. Than I will switch it off as well.
Hello, Binding has been working since two days. Will see what would happen till werkend.
Can you check if you have timeouts in the log file?
If reconnect functionality works fine you may have timeouts followed by a reconnect.
Cheers,
K.
No any timeout so far. When you asked, Iād checked immediatelly but it dissapeared somehow. I havenāt restarted the server since youād asked it last time. It will be also interesting that how it would behave after next server restart.
I have found one:
OH-thingHandler-2 2019-09-26 22:07:36.888 [DEBUG] [ing.paradoxalarm.internal.model.Zone] - Zone Zone 192 state updated to: Opened: false, Tampered: false, LowBattery: false
OH-thingHandler-3 2019-09-26 22:07:41.915 [DEBUG] [l.communication.AbstractCommunicator] - Error receiving packet after reaching the set timeout of 2000ms. Request: RamRequest [getType()=RAM, getRamBlockNumber()=1]
OH-thingHandler-3 2019-09-26 22:07:42.253 [DEBUG] [aradoxalarm.internal.model.Partition] - Partition Epulet: Disarmed, Additional:Ready to arm;Stay instant ready;Force ready;Bypass ready;Inhibit ready;All zones closed;
OH-thingHandler-3 2019-09-26 22:07:42.253 [DEBUG] [aradoxalarm.internal.model.Partition] - Partition Garazs: Disarmed, Additional:Ready to arm;Stay instant ready;Force ready;Bypass ready;Inhibit ready;All zones closed;
OH-thingHandler-3 2019-09-26 22:07:42.253 [DEBUG] [aradoxalarm.internal.model.Partition] - Partition Area 3: Disarmed, Additional:Ready to arm;
OH-thingHandler-3 2019-09-26 22:07:42.253 [DEBUG] [aradoxalarm.internal.model.Partition] - Partition Area 4: Disarmed, Additional:Ready to arm;
OH-thingHandler-3 2019-09-26 22:07:42.253 [DEBUG] [aradoxalarm.internal.model.Partition] - Partition Area 5: Disarmed, Additional:Ready to arm;
OH-thingHandler-3 2019-09-26 22:07:42.253 [DEBUG] [aradoxalarm.internal.model.Partition] - Partition Area 6: Disarmed, Additional:Ready to arm;
OH-thingHandler-3 2019-09-26 22:07:42.253 [DEBUG] [aradoxalarm.internal.model.Partition] - Partition Area 7: Disarmed, Additional:Ready to arm;
OH-thingHandler-3 2019-09-26 22:07:42.253 [DEBUG] [aradoxalarm.internal.model.Partition] - Partition Area 8: Disarmed, Additional:Ready to arm;
OH-thingHandler-3 2019-09-26 22:07:42.253 [DEBUG] [ing.paradoxalarm.internal.model.Zone] - Zone Ajto state updated to: Opened: false, Tampered: false, LowBattery: false
OH-thingHandler-3 2019-09-26 22:07:42.253 [DEBUG] [ing.paradoxalarm.internal.model.Zone] - Zone Eloszoba state updated to: Opened: false, Tampered: false, LowBattery: false
This one is fine. This is only one packet timeout. I usually skip these if the other pages get read correct.
RAM in Evo192 contains 16 pages. We read them in order from 1-16. If any of them for some reason responds wrongly or the packet gets lost in certain timeout we just skip it.
Issue would be if we cannot connect at all to the socket of Paradox. Then the āTIMEOUT !ā text should appear, followed by remediation. You can try if there are timeouts by doing:
grep āTIMEOUTā /yourparadox log folder/*
Cheers,
K.
P.S. I just remembered that youāre under windows. Not sure what the grep in windows is. I guess a search in paradox.log with notepad++ or something would be sufficient.
This āTimeout !ā will be in openhab.log file I guess.
Binding was stopped today see Openhab.log:
2019-09-30 11:28:59.357 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading, caused by java.net.SocketTimeoutException: Read timed out
2019-09-30 11:28:59.357 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - <-- null payload in message
2019-09-30 11:29:00.234 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = ā¦, base URL = http://localhost:8080)
2019-09-30 11:29:00.317 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at org.openhab.binding.paradoxalarm.internal.handlers.ParadoxIP150BridgeHandler.onSocketTimeOutOccurred(ParadoxIP150BridgeHandler.java:294) ~[?:?]
at org.openhab.binding.paradoxalarm.internal.communication.AbstractCommunicator.receivePacket(AbstractCommunicator.java:160) ~[?:?]
at org.openhab.binding.paradoxalarm.internal.communication.AbstractCommunicator.communicateToParadox(AbstractCommunicator.java:105) ~[?:?]
at org.openhab.binding.paradoxalarm.internal.communication.AbstractCommunicator.communicateToParadox(AbstractCommunicator.java:112) ~[?:?]
at org.openhab.binding.paradoxalarm.internal.communication.AbstractCommunicator.submitRequest(AbstractCommunicator.java:98) ~[?:?]
at org.openhab.binding.paradoxalarm.internal.communication.EvoCommunicator.readRAM(EvoCommunicator.java:229) ~[?:?]
at org.openhab.binding.paradoxalarm.internal.communication.EvoCommunicator.refreshMemoryMap(EvoCommunicator.java:218) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
2019-09-30 11:29:01.635 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = ā¦, base URL = http://localhost:8080)
2019-09-30 11:29:03.131 [WARN ] [nal.protocol.MilightV6SessionManager] - Session timeout!
2019-09-30 11:29:03.185 [WARN ] [nal.protocol.MilightV6SessionManager] - Session timeout!
Loggigng was stopped two days because I switched it off accidentally.
Binding was stopped again. I attached the logs. I had an internet outage this time. IP150 connected on local network to the router through a wifi repeater. I reset the binding and will see. One thing is sure, it can run few days without stop. paradox_20191001.log (29.2 KB)