vanackej / risco-mqtt-local

Provide Risco alarm system integration to Home assistant using local TCP communication (no cloud required) and MQTT
MIT License
24 stars 11 forks source link

proxy mode not working #7

Closed kkmaslowski closed 2 years ago

kkmaslowski commented 2 years ago

Hi. I don't see anything in mqtt. I have LightSys 2 and try to configure it in proxy mode.

My config:

{
  "log": "debug",
  "panel": {
    "Panel_Id": "0001",
    "Panel_IP": "192.168.10.33",
    "Panel_Port": 1000,
    "Panel_Password": "5678",
    "AutoDiscover": false,
    "DiscoverCode": false,
    "WatchDogInterval": 10000,
    "SocketMode": "proxy",
    "CloudPort": 33000,
    "CloudUrl": "www.riscocloud.com",
    "Enable_RiscoCloud":  true,
    "ListeningPort": 33000
  },
  "mqtt": {
    "url": "mqtt://192.168.10.100:1883",
    "username": "guest",
    "password": "guest"
  },
  "zones": {
    "default": {
      "off_delay": 30,
      "name_prefix": "Sensor - "
    }
  }
}

Logs attached. proxy.log

I see a lot of timeouts like: 'CUSTLST??' Timeout!!!

vanackej commented 2 years ago

About the CUSTLST?, I don't known. Maybe a message from Cloud socket. I'll have a look.

Your panel connexion seems ok, you should enable AutoDiscover option. This option was present in the library I forked, but it's not useful and must be removed. Messages are published to MQTT once discovery is completed. Try to remove the AutoDiscover option and let me know if you see MQTT messages (with a debug log if not)

kkmaslowski commented 2 years ago

I removed AutoDiscover option. My current config:

{
  "log": "debug",
  "panel": {
    "Panel_Id": "0001",
    "Panel_IP": "192.168.10.33",
    "Panel_Port": 1000,
    "Panel_Password": "5678",
    "WatchDogInterval": 10000,
    "SocketMode": "proxy",
    "Enable_RiscoCloud": true,
    "DiscoverCode": false,
    "ListeningPort": 33000,
    "CloudUrl": "www.riscocloud.com",
    "CloudPort": 33000
  },
  "mqtt": {
    "url": "mqtt://192.168.10.100:1883",
    "username": "guest",
    "password": "guest"
  }
}

Logs without debug:

12/21/2021, 5:51:46 PM [verbose] Start Connection to Panel
[2,5,11,23,47,94,189,122,244,232,208,161,66,133,11,22,45,90,181,107,214,173,90,180,104,208,161,67,135,15,31,63,126,253,251,247,239,223,191,127,255,255,254,252,249,242,229,202,149,43,86,172,88,176,96,193,131,6,12,25,50,100,200,144,32,65,130,5,11,23,47,95,190,125,250,245,234,213,170,85,170,84,168,81,162,68,136,17,35,70,140,24,49,98,197,138,21,42,85,171,87,175,94,188,121,243,230,204,152,49,98,197,138,21,43,86,172,88,177,99,198,141,27,54,109,218,180,105,210,165,74,149,42,85,171,86,173,90,181,106,212,168,80,160,64,129,2,4,9,19,39,78,157,58,117,234,213,170,85,170,85,171,87,175,95,190,124,248,240,225,195,135,15,30,60,120,240,224,193,131,6,12,25,51,102,205,154,53,107,215,175,94,189,122,245,235,215,175,95,190,125,251,246,236,216,176,96,192,129,2,4,8,17,34,68,137,19,39,78,156,56,113,227,199,143,30,61,122,245,234,213,171,86,172,89,179,102,205,154,53,107,215,174,92,185,115,231,207,158,61,123,247,239,223,191]
12/21/2021, 5:51:46 PM [info] Connecting to mqtt server: mqtt://192.168.10.100:1883
12/21/2021, 5:51:47 PM [info] Listening on IP :: and Port 33000
12/21/2021, 5:51:47 PM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/21/2021, 5:51:57 PM [verbose] Panel Socket and RiscoCloud Socket Connected.
- nothing more after 1 hour

In debug I still see a lot of CUSTLST?? Timeout:

12/21/2021, 7:34:28 PM [debug] Command[03] 'CUSTLST??' Timeout!!!
12/21/2021, 7:34:28 PM [debug] Sending Command: CUSTLST??
12/21/2021, 7:34:28 PM [debug] Command CRC Value : A04E
12/21/2021, 7:34:28 PM [debug] Command[03] Sent.
12/21/2021, 7:34:28 PM [debug] Sequence[3] Data Sent : CUSTLST??
12/21/2021, 7:34:28 PM [debug] Received data Buffer from Panel : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 7:34:28 PM [debug] Received data Buffer : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 7:34:28 PM [debug] Command CRC Value : 0CED
12/21/2021, 7:34:28 PM [debug] CRC Not Ok
12/21/2021, 7:34:33 PM [debug] Command[03] 'CUSTLST??' Timeout!!!
12/21/2021, 7:34:33 PM [debug] Sending Command: CUSTLST??
12/21/2021, 7:34:33 PM [debug] Command CRC Value : A04E
12/21/2021, 7:34:33 PM [debug] Command[03] Sent.
12/21/2021, 7:34:33 PM [debug] Sequence[3] Data Sent : CUSTLST??
12/21/2021, 7:34:33 PM [debug] Received data Buffer from Panel : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 7:34:33 PM [debug] Received data Buffer : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 7:34:33 PM [debug] Command CRC Value : 0CED
12/21/2021, 7:34:33 PM [debug] CRC Not Ok
12/21/2021, 7:34:38 PM [debug] Command[03] 'CUSTLST??' Timeout!!!
12/21/2021, 7:34:38 PM [debug] Sending Command: CUSTLST??
12/21/2021, 7:34:38 PM [debug] Command CRC Value : A04E
12/21/2021, 7:34:38 PM [debug] Command[03] Sent.
12/21/2021, 7:34:38 PM [debug] Sequence[3] Data Sent : CUSTLST??
12/21/2021, 7:34:38 PM [debug] Received data Buffer from Panel : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 7:34:38 PM [debug] Received data Buffer : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 7:34:38 PM [debug] Command CRC Value : 0CED
12/21/2021, 7:34:38 PM [debug] CRC Not Ok
12/21/2021, 7:34:43 PM [debug] Command[03] 'CUSTLST??' Timeout!!!
12/21/2021, 7:34:43 PM [debug] Sending Command: CUSTLST??
12/21/2021, 7:34:43 PM [debug] Command CRC Value : A04E
12/21/2021, 7:34:43 PM [debug] Command[03] Sent.
12/21/2021, 7:34:43 PM [debug] Sequence[3] Data Sent : CUSTLST??
12/21/2021, 7:34:43 PM [debug] Received data Buffer from Panel : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 7:34:43 PM [debug] Received data Buffer : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 7:34:43 PM [debug] Command CRC Value : 0CED
12/21/2021, 7:34:43 PM [debug] CRC Not Ok
12/21/2021, 7:34:47 PM [debug] Received data Buffer from Panel : [2,17,52,60,91,68,123,10,140,71,217,197,253,140,111,168,38,59,0,119,240,70,251,128,119,153,127,232,148,117,178,3]
12/21/2021, 7:34:47 PM [debug] Received data Buffer : [2,17,52,60,91,68,123,10,140,71,217,197,253,140,111,168,38,59,0,119,240,70,251,128,119,153,127,232,148,117,178,3]
12/21/2021, 7:34:47 PM [debug] Command CRC Value : 8565
12/21/2021, 7:34:47 PM [debug] CRC Ok
12/21/2021, 7:34:47 PM [debug] Receive[69] Data from Panel, need to send an ACK.

I think it cannot exit from discovery, maybe it loops.

vanackej commented 2 years ago

Ok I think I found one potential problem : 'CUSTLST??' should be 'CUSTLST?', the question mark is duplicated. I'm making a new build with this fix, available in a few minutes (0.2.2). Please try and let me know

kkmaslowski commented 2 years ago

I still see the same messages after container start:

12/21/2021, 8:22:23 PM [debug] Received data Buffer : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 8:22:23 PM [debug] Command CRC Value : 0CED
12/21/2021, 8:22:23 PM [debug] CRC Not Ok
12/21/2021, 8:22:23 PM [debug] Command[03] 'CUSTLST?' Timeout
12/21/2021, 8:22:23 PM [debug] Sending Command: CUSTLST?
12/21/2021, 8:22:23 PM [debug] Command CRC Value : 5197
12/21/2021, 8:22:23 PM [debug] Command[03] Sent.
12/21/2021, 8:22:23 PM [debug] Sequence[3] Data Sent : CUSTLST?
12/21/2021, 8:22:23 PM [debug] Received data Buffer : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 8:22:23 PM [debug] Command CRC Value : 0CED
12/21/2021, 8:22:23 PM [debug] CRC Not Ok
12/21/2021, 8:22:24 PM [debug] Command[03] 'CUSTLST?' Timeout
12/21/2021, 8:22:24 PM [debug] Sending Command: CUSTLST?
12/21/2021, 8:22:24 PM [debug] Command CRC Value : 5197
12/21/2021, 8:22:24 PM [debug] Command[03] Sent.
12/21/2021, 8:22:24 PM [debug] Sequence[3] Data Sent : CUSTLST?
12/21/2021, 8:22:24 PM [debug] Received data Buffer : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 8:22:24 PM [debug] Command CRC Value : 0CED
12/21/2021, 8:22:24 PM [debug] CRC Not Ok
12/21/2021, 8:22:24 PM [debug] Command[03] 'CUSTLST?' Timeout
12/21/2021, 8:22:24 PM [debug] Sending Command: CUSTLST?
12/21/2021, 8:22:24 PM [debug] Command CRC Value : 5197
12/21/2021, 8:22:24 PM [debug] Command[03] Sent.
12/21/2021, 8:22:24 PM [debug] Sequence[3] Data Sent : CUSTLST?
12/21/2021, 8:22:24 PM [debug] Received data Buffer : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 8:22:24 PM [debug] Command CRC Value : 0CED
12/21/2021, 8:22:24 PM [debug] CRC Not Ok
12/21/2021, 8:22:25 PM [debug] Command[03] 'CUSTLST?' Timeout
12/21/2021, 8:22:25 PM [debug] Sending Command: CUSTLST?
12/21/2021, 8:22:25 PM [debug] Command CRC Value : 5197
12/21/2021, 8:22:25 PM [debug] Command[03] Sent.
12/21/2021, 8:22:25 PM [debug] Sequence[3] Data Sent : CUSTLST?
12/21/2021, 8:22:25 PM [debug] Received data Buffer : [2,17,50,54,72,66,124,10,241,41,160,213,224,228,12,190,59,95,121,97,133,34,154,150,106,252,61,235,145,22,204,52,47,108,46,198,203,167,163,228,143,56,173,196,206,190,171,201,213,152,192,16,16,102,226,20,139,80,135,209,61,60,90,124,95,248,212,107,122,178,70,81,44,31,30,235,70,202,161,162,194,154,22,239,16,16,3]
12/21/2021, 8:22:25 PM [debug] Command CRC Value : 0CED
12/21/2021, 8:22:25 PM [debug] CRC Not Ok
12/21/2021, 8:22:25 PM [debug] Command[03] 'CUSTLST?' T

And the same- when i stop container loop ends and everything starts working for 1-2s.

vanackej commented 2 years ago

Have you tried with original library and adding the pause at startup ? Is it the same with it ?

kkmaslowski commented 2 years ago

I tried replacing your library with original using your Dockerfile without success ( i replaced @vanackej/risco-lan-bridge with risco-lan-bridge in package.json +src/lib/risco-mqtt-local.ts). I don't know why, but I get error about config.json format: E config.json is not in json format Config file is ok.

kkmaslowski commented 2 years ago

I managed to add 10s pause to your library (lib/RiscoDirectSocket.js). Nothing changed, still loop with 'Command[03] 'CUSTLST?' Timeout'. Maybe I need to set panel type manually somewhere (LightSys) if autodetect is not working?

vanackej commented 2 years ago

No, setting the panel type would be useless in your situation. The command you see in timeout multiple times is one that is used to establish the encryption protocol with the panel. Not related to panel type.

When I was speaking about trying original library, I was not speaking about the MQTT integration, but about the lan communication library : https://github.com/TJForc/risco-lan-bridge

Please try to set up on of the provided exemples in the documentaiton, like : https://github.com/TJForc/risco-lan-bridge/blob/main/examples/Partitions_Events.js (configure according to your panel) and let's see if panel communication work with it.

kkmaslowski commented 2 years ago

Hi. I configured Partitions_Events.js (ip + RiscoTCPPanel.LightSys instead Agility). Logs: Partitions_Events.log

Don't know if log is ok or not. I used TJForc/risco-lan-bridge library.

vanackej commented 2 years ago

No, it's not ok too. I think there is an issue with your panel ID, or something else. If you have a look at the logs, it tries to guess your panel Id from 9999 to 1 and never finds a good value. From my understanding, PanelId is needd for Honestly I don't know what happens there. I'm currently in progress of a full typescript rewrite of the underneath communication library, addressing many typing issues and concurrency issues. I'll let you know in a few days when available, we'll see from here. Currently the codebase is not clean enough to be able to track your issue correctly.

Le mer. 22 déc. 2021 à 11:37, Kamil Maslowski @.***> a écrit :

Hi. I configured Partitions_Events.js (ip + RiscoTCPPanel.LightSys instead Agility). Logs: Partitions_Events.log https://github.com/vanackej/risco-mqtt-local/files/7762060/Partitions_Events.log

Don't know if log is ok or not.

— Reply to this email directly, view it on GitHub https://github.com/vanackej/risco-mqtt-local/issues/7#issuecomment-999469559, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAECPHIQ34B2D7BNSOOZSODUSGS7PANCNFSM5KQFC3AQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you commented.Message ID: @.***>

kkmaslowski commented 2 years ago

I'm successfully connecting through CS and in Communication->Configuration software Access code is 5678 and Remote ID Code is 0001 (defaults).

Can you check if it's not the same problem as described here: https://github.com/TJForc/risco-lan-bridge/issues/11 ? Interestingly this actually demonstrates that the panel is refusing to talk to the Configuration Software when the access code is correct in #10 - incorrect access codes are met with 'invalid Value' whilst the correct (default) code results in a timeout. (this reinforces my thoughts that in #10 then the problem lies in some form of incomplete disconnect from the panel)

I will also create issue on TJForc project.

vanackej commented 2 years ago

I released the rewritten library version in beta, please update and let me know It's a large rewrite of the codebase. It's supposed to improve many corner cases, but no guarantees. Working really well at home for 24h. Note that proxy mode is disabled for now, I don't have time to migrate it right now (will be done in the coming weeks) In the meantime, you can try this version with direct mode and let me know if you still experience connectivity issues

Le mer. 22 déc. 2021 à 12:54, Kamil Maslowski @.***> a écrit :

I'm successfully connecting through CS and in Communication->Configuration software Access code is 5678 and Remote ID Code is 0001 (defaults).

Can you check if it's not the same problem as described here: TJForc/risco-lan-bridge#11 https://github.com/TJForc/risco-lan-bridge/issues/11 ? Interestingly this actually demonstrates that the panel is refusing to talk to the Configuration Software when the access code is correct in #10 - incorrect access codes are met with 'invalid Value' whilst the correct (default) code results in a timeout. (this reinforces my thoughts that in

10 then the problem lies in some form of incomplete disconnect from the

panel)

— Reply to this email directly, view it on GitHub https://github.com/vanackej/risco-mqtt-local/issues/7#issuecomment-999520292, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAECPHJ2AYLGFDOSHHVQXTLUSG37BANCNFSM5KQFC3AQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you commented.Message ID: @.***>

kkmaslowski commented 2 years ago

I tried it. Container stopped after few minutes with the following error:

12/26/2021, 9:29:57 AM [debug] Pseudo Buffer Created for Panel Id(1): 
[2,5,11,23,47,94,189,122,244,232,208,161,66,133,11,22,45,90,181,107,214,173,90,180,104,208,161,67,135,15,31,63,126,253,251,247,239,223,191,127,255,255,254,252,249,242,229,202,149,43,86,172,88,176,96,193,131,6,12,25,50,100,200,144,32,65,130,5,11,23,47,95,190,125,250,245,234,213,170,85,170,84,168,81,162,68,136,17,35,70,140,24,49,98,197,138,21,42,85,171,87,175,94,188,121,243,230,204,152,49,98,197,138,21,43,86,172,88,177,99,198,141,27,54,109,218,180,105,210,165,74,149,42,85,171,86,173,90,181,106,212,168,80,160,64,129,2,4,9,19,39,78,157,58,117,234,213,170,85,170,85,171,87,175,95,190,124,248,240,225,195,135,15,30,60,120,240,224,193,131,6,12,25,51,102,205,154,53,107,215,175,94,189,122,245,235,215,175,95,190,125,251,246,236,216,176,96,192,129,2,4,8,17,34,68,137,19,39,78,156,56,113,227,199,143,30,61,122,245,234,213,171,86,172,89,179,102,205,154,53,107,215,174,92,185,115,231,207,158,61,123,247,239,223,191]
12/26/2021, 9:29:57 AM [debug] Local GMT Timezone is : +00:00
12/26/2021, 9:29:57 AM [info] autoConnect enabled, starting communication
12/26/2021, 9:29:57 AM [verbose] Start Connection to Panel
12/26/2021, 9:29:57 AM [debug] TCP Socket is not already created, Create It
12/26/2021, 9:29:57 AM [debug] TCP Socket must be created now
12/26/2021, 9:29:57 AM [info] Connecting to mqtt server: mqtt://192.168.10.100:1883
12/26/2021, 9:29:57 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/26/2021, 9:30:27 AM [error] Socket Timeout.
12/26/2021, 9:30:27 AM [error] TCP Socket Disconnected
node:internal/process/promises:246
          triggerUncaughtException(err, true /* fromPromise */);
          ^

AssertionError [ERR_ASSERTION]: Expected 'IsConnected' to be true, but received false. Not connected
    at new AssertionError (node:internal/assert/assertion_error:466:5)
    at assertIsTrue (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/Assertions.js:15:15)
    at RiscoDirectTCPSocket.<anonymous> (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/RiscoBaseSocket.js:207:43)
    at Generator.next (<anonymous>)
    at /usr/src/app/node_modules/tslib/tslib.js:117:75
    at new Promise (<anonymous>)
    at __awaiter (/usr/src/app/node_modules/tslib/tslib.js:113:16)
    at RiscoDirectTCPSocket.sendCommand (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/RiscoBaseSocket.js:204:38)
    at RiscoDirectTCPSocket.<anonymous> (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/RiscoDirectSocket.js:174:28)
    at Generator.next (<anonymous>) {
  generatedMessage: false,
  code: 'ERR_ASSERTION',
  actual: undefined,
  expected: undefined,
  operator: undefined
}
vanackej commented 2 years ago

If you have no additionnal logs, it means your panel socket is already in use and does not accept new coming socket connection. Check what other process is using it. For direct mode to work with single socket TCP module, you also have to disable risco cloud

Le dim. 26 déc. 2021 à 10:58, Kamil Maslowski @.***> a écrit :

I tried it. Container stopped after few minutes with the following error:

12/26/2021, 9:29:57 AM [debug] Pseudo Buffer Created for Panel Id(1): [2,5,11,23,47,94,189,122,244,232,208,161,66,133,11,22,45,90,181,107,214,173,90,180,104,208,161,67,135,15,31,63,126,253,251,247,239,223,191,127,255,255,254,252,249,242,229,202,149,43,86,172,88,176,96,193,131,6,12,25,50,100,200,144,32,65,130,5,11,23,47,95,190,125,250,245,234,213,170,85,170,84,168,81,162,68,136,17,35,70,140,24,49,98,197,138,21,42,85,171,87,175,94,188,121,243,230,204,152,49,98,197,138,21,43,86,172,88,177,99,198,141,27,54,109,218,180,105,210,165,74,149,42,85,171,86,173,90,181,106,212,168,80,160,64,129,2,4,9,19,39,78,157,58,117,234,213,170,85,170,85,171,87,175,95,190,124,248,240,225,195,135,15,30,60,120,240,224,193,131,6,12,25,51,102,205,154,53,107,215,175,94,189,122,245,235,215,175,95,190,125,251,246,236,216,176,96,192,129,2,4,8,17,34,68,137,19,39,78,156,56,113,227,199,143,30,61,122,245,234,213,171,86,172,89,179,102,205,154,53,107,215,174,92,185,115,231,207,158,61,123,247,239,223,191] 12/26/2021, 9:29:57 AM [debug] Local GMT Timezone is : +00:00 12/26/2021, 9:29:57 AM [info] autoConnect enabled, starting communication 12/26/2021, 9:29:57 AM [verbose] Start Connection to Panel 12/26/2021, 9:29:57 AM [debug] TCP Socket is not already created, Create It 12/26/2021, 9:29:57 AM [debug] TCP Socket must be created now 12/26/2021, 9:29:57 AM [info] Connecting to mqtt server: mqtt://192.168.10.100:1883 12/26/2021, 9:29:57 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883 12/26/2021, 9:30:27 AM [error] Socket Timeout. 12/26/2021, 9:30:27 AM [error] TCP Socket Disconnected node:internal/process/promises:246 triggerUncaughtException(err, true / fromPromise /); ^

AssertionError [ERR_ASSERTION]: Expected 'IsConnected' to be true, but received false. Not connected at new AssertionError (node:internal/assert/assertion_error:466:5) at assertIsTrue @./risco-lan-bridge/dist/Assertions.js:15:15) at RiscoDirectTCPSocket. @./risco-lan-bridge/dist/RiscoBaseSocket.js:207:43) at Generator.next () at /usr/src/app/node_modules/tslib/tslib.js:117:75 at new Promise () at __awaiter (/usr/src/app/node_modules/tslib/tslib.js:113:16) at RiscoDirectTCPSocket.sendCommand @./risco-lan-bridge/dist/RiscoBaseSocket.js:204:38) at RiscoDirectTCPSocket. @./risco-lan-bridge/dist/RiscoDirectSocket.js:174:28) at Generator.next () { generatedMessage: false, code: 'ERR_ASSERTION', actual: undefined, expected: undefined, operator: undefined }

— Reply to this email directly, view it on GitHub https://github.com/vanackej/risco-mqtt-local/issues/7#issuecomment-1001141648, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAECPHOKLJYZP2JIU62FDLTUS3RM5ANCNFSM5KQFC3AQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you commented.Message ID: @.***>

kkmaslowski commented 2 years ago

Cloud is disabled and I can connect to panel using CS. Telnet to 192.168.10.33 1000 also works. I tried to start container multiple times, always I got the same error.

vanackej commented 2 years ago

Is previous version able to connect ? Socket layer unable to connect is strange, this part didn't change at all.

In debug the config is supposed to be printed at startup before connection. I don't see it in the logs you provided

Le dim. 26 déc. 2021 à 21:56, Kamil Maslowski @.***> a écrit :

Cloud is disabled and I can connect to panel using CS. Telnet to 192.168.10.33 1000 also works. I tried to start container multiple times, always I got the same error.

— Reply to this email directly, view it on GitHub https://github.com/vanackej/risco-mqtt-local/issues/7#issuecomment-1001240898, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAECPHKJSR26SGYUTUGZNPLUS56RTANCNFSM5KQFC3AQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you commented.Message ID: @.***>

kkmaslowski commented 2 years ago

I attached full log. risco.log

kkmaslowski commented 2 years ago

I restarted panel (cut power for half a day). No change. Still not connecting, log looks the same as 3 days ago. I can connect to 192.168.10.33:1000 using telnet from the same server and from CS software (different windows machine).

Loading config from: /usr/src/app/config.json
12/30/2021, 10:01:52 AM [debug] User config:
{
  "log": "debug",
  "panel": {
    "Panel_Id": "0001",
    "Panel_IP": "192.168.10.33",
    "Panel_Port": 1000,
    "Panel_Password": "5678",
    "WatchDogInterval": 10000
  },
  "mqtt": {
    "url": "mqtt://192.168.10.100:1883",
    "username": "guest",
    "password": "guest"
  }
}
12/30/2021, 10:01:52 AM [debug] Merged config:
{
  "log": "debug",
  "ha_discovery_prefix_topic": "homeassistant",
  "panel": {
    "Panel_Id": "0001",
    "Panel_IP": "192.168.10.33",
    "Panel_Port": 1000,
    "Panel_Password": "5678",
    "WatchDogInterval": 10000
  },
  "zones": {
    "default": {
      "off_delay": 0,
      "device_class": "motion",
      "name_prefix": ""
    }
  },
  "mqtt": {
    "url": "mqtt://192.168.10.100:1883",
    "reconnectPeriod": 5000,
    "clientId": "risco-mqtt",
    "will": {
      "topic": "riscopanel/alarm/status",
      "payload": "offline",
      "qos": 1,
      "retain": true,
      "properties": {
        "willDelayInterval": 30
      }
    },
    "username": "guest",
    "password": "guest"
  }
}
12/30/2021, 10:01:52 AM [debug] Pseudo Buffer Created for Panel Id(1): 
[2,5,11,23,47,94,189,122,244,232,208,161,66,133,11,22,45,90,181,107,214,173,90,180,104,208,161,67,135,15,31,63,126,253,251,247,239,223,191,127,255,255,254,252,249,242,229,202,149,43,86,172,88,176,96,193,131,6,12,25,50,100,200,144,32,65,130,5,11,23,47,95,190,125,250,245,234,213,170,85,170,84,168,81,162,68,136,17,35,70,140,24,49,98,197,138,21,42,85,171,87,175,94,188,121,243,230,204,152,49,98,197,138,21,43,86,172,88,177,99,198,141,27,54,109,218,180,105,210,165,74,149,42,85,171,86,173,90,181,106,212,168,80,160,64,129,2,4,9,19,39,78,157,58,117,234,213,170,85,170,85,171,87,175,95,190,124,248,240,225,195,135,15,30,60,120,240,224,193,131,6,12,25,51,102,205,154,53,107,215,175,94,189,122,245,235,215,175,95,190,125,251,246,236,216,176,96,192,129,2,4,8,17,34,68,137,19,39,78,156,56,113,227,199,143,30,61,122,245,234,213,171,86,172,89,179,102,205,154,53,107,215,174,92,185,115,231,207,158,61,123,247,239,223,191]
12/30/2021, 10:01:52 AM [debug] Local GMT Timezone is : +00:00
12/30/2021, 10:01:52 AM [info] autoConnect enabled, starting communication
12/30/2021, 10:01:52 AM [verbose] Start Connection to Panel
12/30/2021, 10:01:52 AM [debug] TCP Socket is not already created, Create It
12/30/2021, 10:01:52 AM [debug] TCP Socket must be created now
12/30/2021, 10:01:52 AM [info] Connecting to mqtt server: mqtt://192.168.10.100:1883
12/30/2021, 10:01:52 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/30/2021, 10:02:22 AM [error] Socket Timeout.
12/30/2021, 10:02:22 AM [error] TCP Socket Disconnected
node:internal/process/promises:246
          triggerUncaughtException(err, true /* fromPromise */);
          ^

AssertionError [ERR_ASSERTION]: Expected 'IsConnected' to be true, but received false. Not connected
    at new AssertionError (node:internal/assert/assertion_error:466:5)
    at assertIsTrue (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/Assertions.js:15:15)
    at RiscoDirectTCPSocket.<anonymous> (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/RiscoBaseSocket.js:207:43)
    at Generator.next (<anonymous>)
    at /usr/src/app/node_modules/tslib/tslib.js:117:75
    at new Promise (<anonymous>)
    at __awaiter (/usr/src/app/node_modules/tslib/tslib.js:113:16)
    at RiscoDirectTCPSocket.sendCommand (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/RiscoBaseSocket.js:204:38)
    at RiscoDirectTCPSocket.<anonymous> (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/RiscoDirectSocket.js:174:28)
    at Generator.next (<anonymous>) {
  generatedMessage: false,
  code: 'ERR_ASSERTION',
  actual: undefined,
  expected: undefined,
  operator: undefined
}
vanackej commented 2 years ago

Did you update to the version published yesterday ? 0.3.0 Many updates in it, proxy mode added back. Please try this version and post update here

Le jeu. 30 déc. 2021 à 11:07, Kamil Maslowski @.***> a écrit :

I restarted panel (cut power for half a day). No change. Still not connecting, log looks the same as 3 days ago. I can connect to 192.168.10.33:1000 using telnet from the same server and from CS software (different windows machine).

Loading config from: /usr/src/app/config.json 12/30/2021, 10:01:52 AM [debug] User config: { "log": "debug", "panel": { "Panel_Id": "0001", "Panel_IP": "192.168.10.33", "Panel_Port": 1000, "Panel_Password": "5678", "WatchDogInterval": 10000 }, "mqtt": { "url": "mqtt://192.168.10.100:1883", "username": "guest", "password": "guest" } } 12/30/2021, 10:01:52 AM [debug] Merged config: { "log": "debug", "ha_discovery_prefix_topic": "homeassistant", "panel": { "Panel_Id": "0001", "Panel_IP": "192.168.10.33", "Panel_Port": 1000, "Panel_Password": "5678", "WatchDogInterval": 10000 }, "zones": { "default": { "off_delay": 0, "device_class": "motion", "name_prefix": "" } }, "mqtt": { "url": "mqtt://192.168.10.100:1883", "reconnectPeriod": 5000, "clientId": "risco-mqtt", "will": { "topic": "riscopanel/alarm/status", "payload": "offline", "qos": 1, "retain": true, "properties": { "willDelayInterval": 30 } }, "username": "guest", "password": "guest" } } 12/30/2021, 10:01:52 AM [debug] Pseudo Buffer Created for Panel Id(1): [2,5,11,23,47,94,189,122,244,232,208,161,66,133,11,22,45,90,181,107,214,173,90,180,104,208,161,67,135,15,31,63,126,253,251,247,239,223,191,127,255,255,254,252,249,242,229,202,149,43,86,172,88,176,96,193,131,6,12,25,50,100,200,144,32,65,130,5,11,23,47,95,190,125,250,245,234,213,170,85,170,84,168,81,162,68,136,17,35,70,140,24,49,98,197,138,21,42,85,171,87,175,94,188,121,243,230,204,152,49,98,197,138,21,43,86,172,88,177,99,198,141,27,54,109,218,180,105,210,165,74,149,42,85,171,86,173,90,181,106,212,168,80,160,64,129,2,4,9,19,39,78,157,58,117,234,213,170,85,170,85,171,87,175,95,190,124,248,240,225,195,135,15,30,60,120,240,224,193,131,6,12,25,51,102,205,154,53,107,215,175,94,189,122,245,235,215,175,95,190,125,251,246,236,216,176,96,192,129,2,4,8,17,34,68,137,19,39,78,156,56,113,227,199,143,30,61,122,245,234,213,171,86,172,89,179,102,205,154,53,107,215,174,92,185,115,231,207,158,61,123,247,239,223,191] 12/30/2021, 10:01:52 AM [debug] Local GMT Timezone is : +00:00 12/30/2021, 10:01:52 AM [info] autoConnect enabled, starting communication 12/30/2021, 10:01:52 AM [verbose] Start Connection to Panel 12/30/2021, 10:01:52 AM [debug] TCP Socket is not already created, Create It 12/30/2021, 10:01:52 AM [debug] TCP Socket must be created now 12/30/2021, 10:01:52 AM [info] Connecting to mqtt server: mqtt://192.168.10.100:1883 12/30/2021, 10:01:52 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883 12/30/2021, 10:02:22 AM [error] Socket Timeout. 12/30/2021, 10:02:22 AM [error] TCP Socket Disconnected node:internal/process/promises:246 triggerUncaughtException(err, true / fromPromise /); ^

AssertionError [ERR_ASSERTION]: Expected 'IsConnected' to be true, but received false. Not connected at new AssertionError (node:internal/assert/assertion_error:466:5) at assertIsTrue @./risco-lan-bridge/dist/Assertions.js:15:15) at RiscoDirectTCPSocket. @./risco-lan-bridge/dist/RiscoBaseSocket.js:207:43) at Generator.next () at /usr/src/app/node_modules/tslib/tslib.js:117:75 at new Promise () at __awaiter (/usr/src/app/node_modules/tslib/tslib.js:113:16) at RiscoDirectTCPSocket.sendCommand @./risco-lan-bridge/dist/RiscoBaseSocket.js:204:38) at RiscoDirectTCPSocket. @./risco-lan-bridge/dist/RiscoDirectSocket.js:174:28) at Generator.next () { generatedMessage: false, code: 'ERR_ASSERTION', actual: undefined, expected: undefined, operator: undefined }

— Reply to this email directly, view it on GitHub https://github.com/vanackej/risco-mqtt-local/issues/7#issuecomment-1002958319, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAECPHOASAXJHAGFVJPWQNDUTQVNPANCNFSM5KQFC3AQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you commented.Message ID: @.***>

pergolafabio commented 2 years ago

hey @vanackej as discussed earlier, i tried today your new 0.3.0 version, i created a local addon in HA for now with below config

{
  "name": "Risco MQTT Bridge",
  "version": "1",
  "slug": "risco-mqtt-local",
  "description": "Risco Local/Cloud Integration",
  "startup": "application",
  "arch": ["aarch64", "amd64", "armhf", "armv7", "i386"],
  "host_network": true,
  "ports": {
    "33000/tcp": 33000
  },    
  "log": "debug",
  "panel": {
    "Panel_IP": "192.168.0.26",
    "Panel_Port": 1000, 
    "Panel_Password": 5678,
    "Panel_Id": "0001",
    "WatchDogInterval": 10000,
    "Disable_RiscoCloud":  true,
    "Enable_RiscoCloud":  true,
    "DiscoverCode":  false,
    "SocketMode": "proxy",
    "ListeningPort": 33000,
    "CloudPort": 33000,
    "CloudUrl": "www.riscocloud.com"
  },
  "mqtt": {
    "url": "mqtt://localhost:1883",
    "username": "mqtt",
    "password": "mqtt",
    "zone-label-prefix": ""
  }  
}

as you can see i added some proxy settings, so the ip settings entered are ignored, but upon starting the container, it doesnt start the proxy i think? it looks like the proxy settings in the config.json are ignored and its connecting to a panel?

Where is that 192.168.0.100 coming from?

12/30/2021, 9:35:29 PM [debug] Local GMT Timezone is : +01:00
12/30/2021, 9:35:29 PM [info] autoConnect enabled, starting communication
12/30/2021, 9:35:29 PM [verbose] Start Connection to Panel
12/30/2021, 9:35:29 PM [debug] TCP Socket is not already created, Create It
12/30/2021, 9:35:29 PM [debug] TCP Socket must be created now
12/30/2021, 9:35:29 PM [info] Connecting to mqtt server: mqtt://localhost:1883
12/30/2021, 9:35:29 PM [info] Connected on mqtt server: mqtt://localhost:1883
12/30/2021, 9:35:29 PM [info] Panel is not connected, waiting
12/30/2021, 9:35:31 PM [error] Socket Error : Error: connect EHOSTUNREACH 192.168.0.100:1000
12/30/2021, 9:35:31 PM [error] TCP Socket Disconnected
12/30/2021, 9:35:31 PM [debug] Socket Disconnected.
12/30/2021, 9:35:31 PM [error] Socket Closed.
pergolafabio commented 2 years ago

i uses the same config.json as before with your first versions

vanackej commented 2 years ago

Config keys naming changed a few versions ago. Have a look at config.json exemple from readme. I don't think 192.168.0.100 is the IP of your panel

Le jeu. 30 déc. 2021 à 21:46, pergolafabio @.***> a écrit :

i uses the same config.json as before with your first versions

— Reply to this email directly, view it on GitHub https://github.com/vanackej/risco-mqtt-local/issues/7#issuecomment-1003176238, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAECPHMMD7ZBIODVGACUSRDUTTAIXANCNFSM5KQFC3AQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you were mentioned.Message ID: @.***>

pergolafabio commented 2 years ago

Ok, gonna try again later...didn't notice the JSON was changed.... But where is that 192.168.0.100 coming from anyway?

kkmaslowski commented 2 years ago

Hi. I tried 0.3.0 version and now problem is different. When panel password is correct I got warning about timeout and it starts guessing panel Id without success:

12/31/2021, 7:28:29 AM [warn] Command[1] 'RMT=5678' Timeout
12/31/2021, 7:28:30 AM [warn] Bad Panel Id: 1. Trying to find the right one
12/31/2021, 7:28:35 AM [error] No remaining possible Panel Id, abandon
12/31/2021, 7:28:35 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/31/2021, 7:28:35 AM [info] Panel is not connected, waiting
12/31/2021, 7:28:37 AM [error] Unable to connect to the control panel.
12/31/2021, 7:28:37 AM [warn] Command[NaN] Wrong CRC value for the response.
12/31/2021, 7:28:42 AM [warn] Command[4] 'DCN' Timeout
12/31/2021, 7:28:42 AM [warn] Command[NaN] Wrong CRC value for the response.
12/31/2021, 7:28:45 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/31/2021, 7:28:45 AM [info] Panel is not connected, waiting
12/31/2021, 7:28:47 AM [warn] Command[4] 'DCN' Timeout
12/31/2021, 7:28:47 AM [warn] Command[NaN] Wrong CRC value for the response.
12/31/2021, 7:28:52 AM [warn] Command[4] 'DCN' Timeout
12/31/2021, 7:28:52 AM [warn] Command[NaN] Wrong CRC value for the response.
12/31/2021, 7:28:55 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/31/2021, 7:28:55 AM [info] Panel is not connected, waiting
12/31/2021, 7:28:57 AM [warn] Command[4] 'DCN' Timeout
12/31/2021, 7:28:57 AM [warn] Command[NaN] Wrong CRC value for the response.
12/31/2021, 7:28:58 AM [warn] Command[51] Wrong CRC value for the response.
12/31/2021, 7:29:01 AM [warn] Command[51] receivedId is the same as lastReceivedId, ignoring this panel message
12/31/2021, 7:29:02 AM [warn] Command[4] 'DCN' Timeout
12/31/2021, 7:29:02 AM [warn] Command[NaN] Wrong CRC value for the response.
12/31/2021, 7:29:04 AM [warn] Command[51] receivedId is the same as lastReceivedId, ignoring this panel message

But when I set bad panel password (1234 like in your example) it starts guessing password till 5678 and after that everything starts working correctly!!

12/31/2021, 7:36:42 AM [info] autoConnect enabled, starting communication
12/31/2021, 7:36:42 AM [info] Connecting to mqtt server: mqtt://192.168.10.100:1883
12/31/2021, 7:36:42 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/31/2021, 7:36:42 AM [info] Panel is not connected, waiting
12/31/2021, 7:36:47 AM [warn] Command[1] 'RMT=1234' Timeout
12/31/2021, 7:36:47 AM [warn] Command[1] Receipt of an error code: Invalid Value
12/31/2021, 7:36:47 AM [warn] Provided password is incorrect
12/31/2021, 7:36:47 AM [info] Trying to guess password (brut force)
12/31/2021, 7:36:47 AM [info] Trying passwords from 0000 to 9999...
12/31/2021, 7:36:47 AM [info] 0000 to 0099...
12/31/2021, 7:36:52 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/31/2021, 7:36:52 AM [info] Panel is not connected, waiting
12/31/2021, 7:36:52 AM [info] 0100 to 0199...
12/31/2021, 7:36:58 AM [info] 0200 to 0299...
12/31/2021, 7:37:02 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/31/2021, 7:37:02 AM [info] Panel is not connected, waiting
12/31/2021, 7:37:05 AM [warn] Command[3] 'RMT=0246' Timeout
12/31/2021, 7:37:08 AM [info] 0300 to 0399...
12/31/2021, 7:37:12 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/31/2021, 7:37:12 AM [info] Panel is not connected, waiting
12/31/2021, 7:37:13 AM [info] 0400 to 0499...
12/31/2021, 7:37:19 AM [info] 0500 to 0599...
12/31/2021, 7:37:22 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/31/2021, 7:37:22 AM [info] Panel is not connected, waiting
12/31/2021, 7:37:27 AM [warn] Command[31] 'RMT=0568' Timeout
12/31/2021, 7:37:29 AM [info] 0600 to 0699...
12/31/2021, 7:37:32 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/31/2021, 7:37:32 AM [info] Panel is not connected, waiting
12/31/2021, 7:37:34 AM [info] 0700 to 0799...
12/31/2021, 7:37:40 AM [info] 0800 to 0899...

...
...
12/31/2021, 7:42:39 AM [info] 5600 to 5699...
12/31/2021, 7:42:43 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
12/31/2021, 7:42:43 AM [info] Panel is not connected, waiting
12/31/2021, 7:42:43 AM [info] Discovered Access Code : 5678
12/31/2021, 7:42:44 AM [info] Panel info: LightSys/RP432, FW 2.59
12/31/2021, 7:42:44 AM [info] Panel options: 4 parts, 32 zones, 14 outputs, Pir Cam support: false
12/31/2021, 7:42:48 AM [warn] Command[16] Receipt of an error code: Device Doesn't Exists
12/31/2021, 7:42:48 AM [info] Output does not exists, stopping outputs discovery
12/31/2021, 7:42:48 AM [info] Panel is ready, subscribing to panel partitions and zones events
12/31/2021, 7:42:48 AM [info] Panel and MQTT communications are ready
12/31/2021, 7:42:48 AM [info] Publishing Home Assistant discovery info
12/31/2021, 7:42:48 AM [info] [Panel => MQTT][Discovery] Published alarm_control_panel to HA on partition 1
12/31/2021, 7:42:48 AM [info] [Panel => MQTT][Discovery] Published alarm_control_panel to HA on partition 2
12/31/2021, 7:42:48 AM [info] [Panel => MQTT][Discovery] Published alarm_control_panel to HA on partition 3
12/31/2021, 7:42:48 AM [info] [Panel => MQTT][Discovery] Published binary_sensor to HA: Zone label = Wiatrołap, HA name = Wiatrołap

Please check if it's not the same problem as described in: https://github.com/TJForc/risco-lan-bridge/issues/11 Or maybe it's still problem with lack of 10s delay on start: https://github.com/vanackej/risco-mqtt-local/issues/6 I'm attaching info logs:

wrong_password.log correct_password.log and debug: wrong_password-debug.log correct_password-debug.log

vanackej commented 2 years ago

A lot of strange things are happening here. First I see a lot of timeouts, but that should not be a problem. Then, there is a kind of mqtt connection loop that is really strange.

Wrong password -> Password found by library => Entryption OK => Parts/zones correctly discovered -> MQTT connexion loop Good password -> Entryption KO -> Unable to set up encryption => Process exit

I will try adding more logs, but I tested both situations (bad password or panel ID) and behavior is perfectly stable with my LightSys 2 panel. Panel Id and code are discovered as expected and connection is then very stable.

I strongly suspect you have a flacky network, because of very high number of timeouts and CRC errors I see in your logs

vanackej commented 2 years ago

Here is a log with bad panel ID, bad code and even an initial socket disconnection that show how it's supposed to work:

12/31/2021, 12:50:42 PM [info] autoConnect enabled, starting communication
12/31/2021, 12:50:42 PM [info] Connecting to mqtt server: mqtt://192.168.1.30:1883
12/31/2021, 12:50:42 PM [info] Connected on mqtt server: mqtt://192.168.1.30:1883
12/31/2021, 12:50:42 PM [info] Panel is not connected, waiting
12/31/2021, 12:50:42 PM [warn] Command[28] Command response was unexpected, ignoring. Data[N06]. sequenceId[1]
12/31/2021, 12:50:42 PM [warn] Command[28] Receipt of an error code: Invalid Value
12/31/2021, 12:50:43 PM [warn] Command[1] Receipt of an error code: Invalid Value
12/31/2021, 12:50:43 PM [warn] Provided password is incorrect
12/31/2021, 12:50:43 PM [info] Trying to guess password (brut force)
12/31/2021, 12:50:43 PM [info] Trying passwords from 0000 to 9999...
12/31/2021, 12:50:43 PM [info] 0000 to 0099...
12/31/2021, 12:50:46 PM [info] 0100 to 0199...
12/31/2021, 12:50:49 PM [info] 0200 to 0299...
12/31/2021, 12:50:52 PM [error] Socket Closed.
12/31/2021, 12:50:52 PM [error] TCP Socket Disconnected
Loading config from: /usr/src/app/config.json
12/31/2021, 12:50:53 PM [info] autoConnect enabled, starting communication
12/31/2021, 12:50:53 PM [info] Connecting to mqtt server: mqtt://192.168.1.30:1883
12/31/2021, 12:50:53 PM [info] Connected on mqtt server: mqtt://192.168.1.30:1883
12/31/2021, 12:50:53 PM [info] Panel is not connected, waiting
12/31/2021, 12:50:53 PM [warn] Command[40] Command response was unexpected, ignoring. Data[N06]. sequenceId[1]
12/31/2021, 12:50:53 PM [warn] Command[40] Receipt of an error code: Invalid Value
12/31/2021, 12:50:54 PM [warn] Command[1] Receipt of an error code: Invalid Value
12/31/2021, 12:50:54 PM [warn] Provided password is incorrect
12/31/2021, 12:50:54 PM [info] Trying to guess password (brut force)
12/31/2021, 12:50:54 PM [info] Trying passwords from 0000 to 9999...
12/31/2021, 12:50:54 PM [info] 0000 to 0099...
12/31/2021, 12:50:57 PM [info] 0100 to 0199...
12/31/2021, 12:51:00 PM [info] 0200 to 0299...
12/31/2021, 12:51:03 PM [info] 0300 to 0399...
12/31/2021, 12:51:06 PM [info] 0400 to 0499...
12/31/2021, 12:51:12 PM [warn] Command[19] 'RMT=0409' Timeout
12/31/2021, 12:51:15 PM [info] 0500 to 0599...
12/31/2021, 12:51:18 PM [info] 0600 to 0699...
12/31/2021, 12:51:21 PM [info] 0700 to 0799...
12/31/2021, 12:51:29 PM [warn] Command[17] 'RMT=0799' Timeout
12/31/2021, 12:51:29 PM [info] 0800 to 0899...
12/31/2021, 12:51:32 PM [info] 0900 to 0999...
12/31/2021, 12:51:35 PM [info] 1000 to 1099...
12/31/2021, 12:51:39 PM [info] 1100 to 1199...
12/31/2021, 12:51:42 PM [info] 1200 to 1299...
12/31/2021, 12:51:45 PM [info] 1300 to 1399...
12/31/2021, 12:51:48 PM [info] 1400 to 1499...
12/31/2021, 12:51:48 PM [info] Discovered Access Code : 1402
12/31/2021, 12:51:48 PM [warn] Command[NaN] Wrong CRC value for the response.
12/31/2021, 12:51:49 PM [warn] Bad Panel Id: 22. Trying to find the right one
12/31/2021, 12:51:50 PM [info] Panel Id is possible candidate : 129
12/31/2021, 12:51:50 PM [info] Panel Id 129 is incorrect
12/31/2021, 12:51:50 PM [info] Panel Id is possible candidate : 1
12/31/2021, 12:51:50 PM [info] Discovered Panel Id: 1
12/31/2021, 12:51:54 PM [info] Panel info: LightSys/RP432, FW 5.72
12/31/2021, 12:51:54 PM [info] Panel options: 4 parts, 50 zones, 32 outputs, Pir Cam support: false
12/31/2021, 12:52:00 PM [warn] Command[39] 'ZLNKTYP26?' Timeout
12/31/2021, 12:52:02 PM [warn] Command[40] Receipt of an error code: Device Doesn't Exists
12/31/2021, 12:52:02 PM [info] Output does not exists, stopping outputs discovery
12/31/2021, 12:52:02 PM [info] Panel is ready, subscribing to panel partitions and zones events
12/31/2021, 12:52:02 PM [info] Panel and MQTT communications are ready
12/31/2021, 12:52:02 PM [info] Publishing Home Assistant discovery info
12/31/2021, 12:52:02 PM [info] [Panel => MQTT][Discovery] Published alarm_control_panel to HA on partition 1
12/31/2021, 12:52:02 PM [info] [Panel => MQTT][Discovery] Published binary_sensor to HA: Zone label = GARAGE, HA name = Détecteur - GARAGE
12/31/2021, 12:52:02 PM [info] [Panel => MQTT][Discovery] Published binary_sensor to HA: Zone label = ENTREE, HA name = Détecteur - ENTREE
12/31/2021, 12:52:02 PM [info] [Panel => MQTT][Discovery] Published binary_sensor to HA: Zone label = SALLE A MANGER, HA name = Détecteur - SALLE A MANGER
12/31/2021, 12:52:02 PM [info] [Panel => MQTT][Discovery] Published binary_sensor to HA: Zone label = SALON, HA name = Détecteur - SALON
12/31/2021, 12:52:02 PM [info] Subscribing to Home assistant commands topics
12/31/2021, 12:52:02 PM [info] Subscribe on riscopanel/alarm/1/set topic
12/31/2021, 12:52:02 PM [info] Publishing initial partitions and zones state to Home assistant
12/31/2021, 12:52:02 PM [info] [Panel => MQTT] Published alarm status disarmed on partition 1
12/31/2021, 12:52:02 PM [info] Initialization completed
kkmaslowski commented 2 years ago

Why everything works as expected only when I provide wrong panel password and don't work when it's correct? Maybe with my panel first try to send 'RMT=xxx' should be later (after 10s) or it should be repeated, because it always finishes with timeout? Look at logs with wrong password and good - both finishes with timeout. Bad password:

12/31/2021, 7:36:42 AM [info] Panel is not connected, waiting
12/31/2021, 7:36:47 AM [warn] Command[1] 'RMT=1234' Timeout
12/31/2021, 7:36:47 AM [warn] Command[1] Receipt of an error code: Invalid Value
12/31/2021, 7:36:47 AM [warn] Provided password is incorrect
12/31/2021, 7:36:47 AM [info] Trying to guess password (brut force)

good password: 12/31/2021, 7:28:29 AM [warn] Command[1] 'RMT=5678' Timeout

Is there a method to disable guessing password? Maybe command should be repeated and it would start to work on second try. Or can I set somewhere in code 10s sleep before that command (where to add it)?

Maybe problem is specific to my mono-socket RW132IP. You have normal multi-socket version?

pergolafabio commented 2 years ago

Just for info, why are you not trying the proxy? I tested it a few weeks ago, was working great, except for sometimes a socket issue after x amount of hours...

Not tested the new version, is it reconnects , itry changing it in a few days

pergolafabio commented 2 years ago

hey @vanackej , new config.json file below , but seems the proxy is not starting i think? it still wants to connect to a panel?

12/31/2021, 2:22:09 PM [debug] Local GMT Timezone is : +01:00
12/31/2021, 2:22:09 PM [info] autoConnect enabled, starting communication
12/31/2021, 2:22:09 PM [verbose] Start Connection to Panel
12/31/2021, 2:22:09 PM [debug] TCP Socket is not already created, Create It
12/31/2021, 2:22:09 PM [debug] TCP Socket must be created now
12/31/2021, 2:22:09 PM [info] Connecting to mqtt server: mqtt://localhost:1883
12/31/2021, 2:22:09 PM [info] Connected on mqtt server: mqtt://localhost:1883
12/31/2021, 2:22:09 PM [info] Panel is not connected, waiting
12/31/2021, 2:22:39 PM [error] Socket Timeout.
12/31/2021, 2:22:39 PM [debug] Socket Destroyed.
12/31/2021, 2:22:39 PM [error] TCP Socket Disconnected
12/31/2021, 2:22:39 PM [debug] Socket Disconnected.
12/31/2021, 2:22:49 PM [verbose] Start Connection to Panel
12/31/2021, 2:22:49 PM [debug] TCP Socket is already created, Connect It
12/31/2021, 2:22:49 PM [debug] TCP Socket must be created now
12/31/2021, 2:23:19 PM [error] Socket Timeout.
12/31/2021, 2:23:19 PM [debug] Socket Destroyed.
12/31/2021, 2:23:19 PM [error] TCP Socket Disconnected

json:

{
  "name": "Risco MQTT Bridge",
  "version": "1",
  "slug": "risco-mqtt-local",
  "description": "Risco Local/Cloud Integration",
  "startup": "application",
  "arch": ["aarch64", "amd64", "armhf", "armv7", "i386"],
  "host_network": true,
  "ports": {
    "33000/tcp": 33000
  },    
  "log": "debug",
  "panel": {
    "panelIp": "192.168.1.150",
    "panelPort": 1000,
    "panelPassword": 1234,
    "panelId": "0001",
    "watchDogInterval": 10000,
    "Disable_RiscoCloud":  true,
    "Enable_RiscoCloud":  true,
    "autoDiscover":  false,
    "SocketMode": "proxy",
    "ListeningPort": 33000,
    "CloudPort": 33000,
    "CloudUrl": "www.riscocloud.com"    
  },
  "mqtt": {
    "url": "mqtt://localhost:1883",
    "username": "mqtt",
    "password": "mqtt"
  },
  "zones": {
    "default": {
      "off_delay": 0,
      "name_prefix": ""
    },
    "GARAGE": {
      "off_delay": 0,
      "device_class": "garage_door",
      "name": "Garage Door",
      "name_prefix": ""
    }
  }
}
vanackej commented 2 years ago

I think your config format is still not ok. Have a look at the properties of the Panel option class in RiscoPanel.ts file You are not in proxy mode here

Le ven. 31 déc. 2021 à 14:33, pergolafabio @.***> a écrit :

hey @vanackej https://github.com/vanackej , new config.json file below , but seems the proxy is not starting i think? it still wants to connect to a panel?

12/31/2021, 2:22:09 PM [debug] Local GMT Timezone is : +01:00 12/31/2021, 2:22:09 PM [info] autoConnect enabled, starting communication 12/31/2021, 2:22:09 PM [verbose] Start Connection to Panel 12/31/2021, 2:22:09 PM [debug] TCP Socket is not already created, Create It 12/31/2021, 2:22:09 PM [debug] TCP Socket must be created now 12/31/2021, 2:22:09 PM [info] Connecting to mqtt server: mqtt://localhost:1883 12/31/2021, 2:22:09 PM [info] Connected on mqtt server: mqtt://localhost:1883 12/31/2021, 2:22:09 PM [info] Panel is not connected, waiting 12/31/2021, 2:22:39 PM [error] Socket Timeout. 12/31/2021, 2:22:39 PM [debug] Socket Destroyed. 12/31/2021, 2:22:39 PM [error] TCP Socket Disconnected 12/31/2021, 2:22:39 PM [debug] Socket Disconnected. 12/31/2021, 2:22:49 PM [verbose] Start Connection to Panel 12/31/2021, 2:22:49 PM [debug] TCP Socket is already created, Connect It 12/31/2021, 2:22:49 PM [debug] TCP Socket must be created now 12/31/2021, 2:23:19 PM [error] Socket Timeout. 12/31/2021, 2:23:19 PM [debug] Socket Destroyed. 12/31/2021, 2:23:19 PM [error] TCP Socket Disconnected

json:

{ "name": "Risco MQTT Bridge", "version": "1", "slug": "risco-mqtt-local", "description": "Risco Local/Cloud Integration", "startup": "application", "arch": ["aarch64", "amd64", "armhf", "armv7", "i386"], "host_network": true, "ports": { "33000/tcp": 33000 },
"log": "debug", "panel": { "panelIp": "192.168.1.150", "panelPort": 1000, "panelPassword": 1234, "panelId": "0001", "watchDogInterval": 10000, "Disable_RiscoCloud": true, "Enable_RiscoCloud": true, "autoDiscover": false, "SocketMode": "proxy", "ListeningPort": 33000, "CloudPort": 33000, "CloudUrl": "www.riscocloud.com"
}, "mqtt": { "url": "mqtt://localhost:1883", "username": "mqtt", "password": "mqtt" }, "zones": { "default": { "off_delay": 0, "name_prefix": "" }, "GARAGE": { "off_delay": 0, "device_class": "garage_door", "name": "Garage Door", "name_prefix": "" } } }

— Reply to this email directly, view it on GitHub https://github.com/vanackej/risco-mqtt-local/issues/7#issuecomment-1003378340, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAECPHO3UTRPRID7YFC6LHTUTWWKJANCNFSM5KQFC3AQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you were mentioned.Message ID: @.***>

vanackej commented 2 years ago

@kkmaslowski timeout is not a problem, as command are automatically retried. Your log for correct/wrong password is fine.

What I don't get is why you have checksum issues with the correct panel id.

I should maybe Introduce an option to disable panel crypto check at startup, and just assume that CRC errors are CRC errors, not an encryption issue...

I'm off for a few days, I'll have a look next week

pergolafabio commented 2 years ago

ok, the options were indeed different then in the readme those 2 below are not needed anymore? i dont want to cloud disable... probaly doenst work anyway if using proxy

    "Disable_RiscoCloud":  true,
    "Enable_RiscoCloud":  true,

anwyay, proxy is up and running, lets see what happens within a few hours/days , disabled watchdog for now on the add-on

1/1/2022, 11:42:27 AM [debug] Local GMT Timezone is : +01:00
1/1/2022, 11:42:27 AM [info] autoConnect enabled, starting communication
1/1/2022, 11:42:27 AM [verbose] Start Connection to Panel
1/1/2022, 11:42:27 AM [debug] TCP Socket is not already created, Create It
1/1/2022, 11:42:27 AM [debug] TCP Socket must be created now
1/1/2022, 11:42:27 AM [info] Connecting to mqtt server: mqtt://localhost:1883
1/1/2022, 11:42:27 AM [info] Listening on IP :: and Port 33000
1/1/2022, 11:42:27 AM [info] Waiting for panel incoming connection... This can take up to 1 or 2 minutes
1/1/2022, 11:42:27 AM [info] Connected on mqtt server: mqtt://localhost:1883
1/1/2022, 11:42:27 AM [info] Panel is not connected, waiting
1/1/2022, 11:47:47 AM [info] Incoming connection from panel received
1/1/2022, 11:47:47 AM [debug] RiscoCloud Socket: connect
1/1/2022, 11:47:47 AM [info] RiscoCloud Socket: ready
1/1/2022, 11:47:47 AM [info] Setting a timer for panel connection in 30000 ms
1/1/2022, 11:47:47 AM [debug] [Panel => Cloud] Forwarding panel packet to cloud: 
pergolafabio commented 2 years ago

first test , if i restart the docker, did it 3 times, the connection restored, so thats good

next test , i took out the network cable, from my panel, put it back in , but then it doesnt reconnect, i always see this loop below

1/1/2022, 12:03:11 PM [warn] Command[25] 'CLOCK' Timeout
1/1/2022, 12:03:11 PM [warn] Command[25] 'CLOCK' Timeout
1/1/2022, 12:03:11 PM [warn] Command[25] 'CLOCK' Timeout
1/1/2022, 12:03:11 PM [debug] Command[25] retrying with a new command Id
1/1/2022, 12:03:11 PM [verbose] Command[25] Sending Command: CLOCK
1/1/2022, 12:03:11 PM [debug] Command[25] Writing command buffer to socket: [2,17,48,48,72,91,96,29,246,109,196,222,226,152,3]
1/1/2022, 12:03:11 PM [debug] Command[25] Data Sent : CLOCK
1/1/2022, 12:03:11 PM [debug] Command[25] retrying with a new command Id
1/1/2022, 12:03:11 PM [verbose] Command[25] Sending Command: CLOCK
1/1/2022, 12:03:11 PM [debug] Command[25] Writing command buffer to socket: [2,17,48,48,72,91,96,29,246,109,196,222,226,152,3]
1/1/2022, 12:03:11 PM [debug] Command[25] Data Sent : CLOCK
1/1/2022, 12:03:11 PM [debug] Command[25] retrying with a new command Id
1/1/2022, 12:03:11 PM [verbose] Command[25] Sending Command: CLOCK
1/1/2022, 12:03:11 PM [debug] Command[25] Writing command buffer to socket: [2,17,48,48,72,91,96,29,246,109,196,222,226,152,3]
1/1/2022, 12:03:11 PM [debug] Command[25] Data Sent : CLOCK
1/1/2022, 12:03:11 PM [warn] Command[25] 'CLOCK' Timeout
1/1/2022, 12:03:11 PM [debug] Command[25] retrying with a new command Id
1/1/2022, 12:03:11 PM [verbose] Command[25] Sending Command: CLOCK
1/1/2022, 12:03:11 PM [debug] Command[25] Writing command buffer to socket: [2,17,48,48,72,91,96,29,246,109,196,222,226,152,3]
1/1/2022, 12:03:11 PM [debug] Command[25] Data Sent : CLOCK
1/1/2022, 12:03:11 PM [warn] Command[25] 'CLOCK' Timeout
1/1/2022, 12:03:11 PM [debug] Command[25] retrying with a new command Id
1/1/2022, 12:03:11 PM [verbose] Command[25] Sending Command: CLOCK
1/1/2022, 12:03:11 PM [debug] Command[25] Writing command buffer to socket: [2,17,48,48,72,91,96,29,246,109,196,222,226,152,3]
1/1/2022, 12:03:11 PM [debug] Command[25] Data Sent : CLOCK

then i did a resart of the add-on, i saw error below, so a second restart was needed

1/1/2022, 12:04:20 PM [debug] [Panel => Bridge] Received unencrypted data Buffer from Panel : [115,170,57,38]
1/1/2022, 12:04:20 PM [debug] Received data Buffer : [115,170,57,38]
1/1/2022, 12:04:20 PM [debug] Command[NaN] CRC Value : FFFF
1/1/2022, 12:04:20 PM [debug] Command[NaN] CRC Not Ok
1/1/2022, 12:04:20 PM [warn] Command[NaN] Wrong CRC value for the response.
1/1/2022, 12:04:20 PM [debug] [Panel => Cloud] Forwarding panel packet to cloud: 
.....

1/1/2022, 12:04:50 PM [verbose] Command[72] Received data from panel: IPCSTT=----
1/1/2022, 12:04:50 PM [debug] Command[72] Data type: Hardware Status
1/1/2022, 12:04:50 PM [error] Panel Socket Closed.
1/1/2022, 12:04:50 PM [debug] RiscoCloud Socket Destroyed.
1/1/2022, 12:04:50 PM [error] TCP Socket Disconnected
node:internal/process/promises:246
          triggerUncaughtException(err, true /* fromPromise */);
          ^
AssertionError [ERR_ASSERTION]: Expected 'panelSocket.destroyed' to be false, but received true. sendCommand(CUSTLST?): Socket is destroyed
    at new AssertionError (node:internal/assert/assertion_error:466:5)
    at assertIsFalse (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/Assertions.js:23:15)
    at RiscoProxyTCPSocket.<anonymous> (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/RiscoBaseSocket.js:211:44)
    at Generator.next (<anonymous>)
    at /usr/src/app/node_modules/tslib/tslib.js:117:75
    at new Promise (<anonymous>)
    at __awaiter (/usr/src/app/node_modules/tslib/tslib.js:113:16)
    at RiscoProxyTCPSocket.sendCommand (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/RiscoBaseSocket.js:209:38)
    at RiscoProxyTCPSocket.<anonymous> (/usr/src/app/node_modules/@vanackej/risco-lan-bridge/dist/RiscoBaseSocket.js:355:39)
    at Generator.next (<anonymous>) {
  generatedMessage: false,
  code: 'ERR_ASSERTION',
  actual: undefined,
  expected: undefined,
  operator: undefined
}
kkmaslowski commented 2 years ago

I tried proxy mode with latest version and had the same results .

Correct password:

Loading config from: /usr/src/app/config.json
1/1/2022, 2:48:49 PM [info] autoConnect enabled, starting communication
1/1/2022, 2:48:49 PM [info] Connecting to mqtt server: mqtt://192.168.10.100:1883
1/1/2022, 2:48:49 PM [info] Listening on IP :: and Port 33000
1/1/2022, 2:48:49 PM [info] Waiting for panel incoming connection... This can take up to 1 or 2 minutes
1/1/2022, 2:48:49 PM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
1/1/2022, 2:48:49 PM [info] Panel is not connected, waiting
1/1/2022, 2:49:01 PM [info] Incoming connection from panel received
1/1/2022, 2:49:01 PM [info] RiscoCloud Socket: ready
1/1/2022, 2:49:01 PM [info] Setting a timer for panel connection in 30000 ms
1/1/2022, 2:49:33 PM [warn] Bad Panel Id: 1. Trying to find the right one
1/1/2022, 2:49:37 PM [error] No remaining possible Panel Id, abandon
1/1/2022, 2:49:39 PM [error] Unable to connect to the control panel.
1/1/2022, 2:49:39 PM [warn] Command[NaN] Wrong CRC value for the response.
1/1/2022, 2:49:44 PM [warn] Command[4] 'DCN' Timeout
1/1/2022, 2:49:45 PM [warn] Command[NaN] Wrong CRC value for the response.
1/1/2022, 2:49:49 PM [warn] Command[4] 'DCN' Timeout
1/1/2022, 2:49:50 PM [warn] Command[NaN] Wrong CRC value for the response.

Wrong password:

Loading config from: /usr/src/app/config.json
1/1/2022, 2:50:18 PM [info] autoConnect enabled, starting communication
1/1/2022, 2:50:18 PM [info] Connecting to mqtt server: mqtt://192.168.10.100:1883
1/1/2022, 2:50:18 PM [info] Listening on IP :: and Port 33000
1/1/2022, 2:50:18 PM [info] Waiting for panel incoming connection... This can take up to 1 or 2 minutes
1/1/2022, 2:50:18 PM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
1/1/2022, 2:50:18 PM [info] Panel is not connected, waiting
1/1/2022, 2:50:26 PM [info] Incoming connection from panel received
1/1/2022, 2:50:26 PM [info] RiscoCloud Socket: ready
1/1/2022, 2:50:26 PM [info] Setting a timer for panel connection in 30000 ms
1/1/2022, 2:50:56 PM [warn] Command[1] Receipt of an error code: Invalid Value
1/1/2022, 2:50:56 PM [warn] Provided password is incorrect
1/1/2022, 2:50:56 PM [info] Trying to guess password (brut force)
1/1/2022, 2:50:56 PM [info] Trying passwords from 0000 to 9999...
1/1/2022, 2:50:56 PM [info] 0000 to 0099...
1/1/2022, 2:51:02 PM [info] 0100 to 0199...
1/1/2022, 2:51:08 PM [info] 0200 to 0299...
...
...
1/1/2022, 2:56:23 PM [info] 5600 to 5699...
1/1/2022, 2:56:28 PM [info] Discovered Access Code : 5678
1/1/2022, 2:56:29 PM [info] Panel info: LightSys/RP432, FW 2.59
1/1/2022, 2:56:29 PM [info] Panel options: 4 parts, 32 zones, 14 outputs, Pir Cam support: false
1/1/2022, 2:56:32 PM [warn] Command[16] Receipt of an error code: Device Doesn't Exists
1/1/2022, 2:56:32 PM [info] Output does not exists, stopping outputs discovery
1/1/2022, 2:56:33 PM [info] Panel is ready, subscribing to panel partitions and zones events
1/1/2022, 2:56:33 PM [info] Panel and MQTT communications are ready
1/1/2022, 2:56:33 PM [info] Publishing Home Assistant discovery info
1/1/2022, 2:56:33 PM [info] [Panel => MQTT][Discovery] Published alarm_control_panel to HA on partition 1
1/1/2022, 2:56:33 PM [info] [Panel => MQTT][Discovery] Published alarm_control_panel to HA on partition 2
1/1/2022, 2:56:33 PM [info] [Panel => MQTT][Discovery] Published alarm_control_panel to HA on partition 3
1/1/2022, 2:56:33 PM [info] [Panel => MQTT][Discovery] Published binary_sensor to HA: Zone label = Wiatrołap, HA name = Wiatrołap
1/1/2022, 2:56:33 PM [info] [Panel => MQTT][Discovery] Published binary_sensor to HA: Zone label = Przedpokój, HA name = Przedpokój
1/1/2022, 2:56:33 PM [info] [Panel => MQTT][Discovery] Published binary_sensor to HA: Zone label = Kuchnia, HA name = 
...
...
1/1/2022, 2:56:33 PM [info] Subscribing to Home assistant commands topics
1/1/2022, 2:56:33 PM [info] Subscribe on riscopanel/alarm/1/set topic
1/1/2022, 2:56:33 PM [info] Subscribe on riscopanel/alarm/2/set topic
1/1/2022, 2:56:33 PM [info] Subscribe on riscopanel/alarm/3/set topic
1/1/2022, 2:56:33 PM [info] Publishing initial partitions and zones state to Home assistant
1/1/2022, 2:56:33 PM [info] [Panel => MQTT] Published alarm status disarmed on partition 1
1/1/2022, 2:56:33 PM [info] [Panel => MQTT] Published alarm status disarmed on partition 2
1/1/2022, 2:56:33 PM [info] [Panel => MQTT] Published alarm status disarmed on partition 3
1/1/2022, 2:56:33 PM [info] Initialization completed

Thanks for your hard work. I can live with slower startup and guessing code, but it would be good to find the reason of that. Happy new year!

vanackej commented 2 years ago

A lot of strange things are happening here. First I see a lot of timeouts, but that should not be a problem. Then, there is a kind of mqtt connection loop that is really strange.

Wrong password -> Password found by library => Entryption OK => Parts/zones correctly discovered -> MQTT connexion loop Good password -> Entryption KO -> Unable to set up encryption => Process exit

I will try adding more logs, but I tested both situations (bad password or panel ID) and behavior is perfectly stable with my LightSys 2 panel. Panel Id and code are discovered as expected and connection is then very stable.

I strongly suspect you have a flacky network, because of very high number of timeouts and CRC errors I see in your logs

@kkmaslowski The MQTT connection loop in your log clearly indicates that you have 2 processes parallel processes that connect to MQTT server using the same client ID (the one used for the library. Each time one get disconnected, it attempts to reconnect and kicks off the other one. Please kill all concurrent library instance process and ensure there is only one running instance.

vanackej commented 2 years ago

@pergolafabio I made small improvements in disconnection/command retries. Will release it today.

I close this issue for now, as for me proxy mode is working now (maybe not perfect, but still working). Please reopen more focused issues with logs and accurate description if needed.

kkmaslowski commented 2 years ago

@vanackej proxy mode and direct connection works for me ok now. There is still issue with correct code. I need to start proxy or direct mode with wrong code. I will create separate issue for that with debug logs if needed. For me there is no difference on 0.3.1, still the same with good pasword:

Loading config from: /usr/src/app/config.json
1/3/2022, 11:42:03 AM [info] autoConnect enabled, starting communication
1/3/2022, 11:42:03 AM [info] Connecting to mqtt server: mqtt://192.168.10.100:1883
1/3/2022, 11:42:03 AM [info] Connected on mqtt server: mqtt://192.168.10.100:1883
1/3/2022, 11:42:03 AM [info] Panel is not connected, waiting
1/3/2022, 11:42:11 AM [warn] Command[1] 'RMT=5678' Timeout
1/3/2022, 11:42:11 AM [warn] Bad Panel Id: 1. Trying to find the right one
1/3/2022, 11:42:15 AM [error] No remaining possible Panel Id, abandon
1/3/2022, 11:42:15 AM [error] Unable to connect to the control panel.
1/3/2022, 11:42:15 AM [warn] Command[NaN] Wrong CRC value for the response.
1/3/2022, 11:42:16 AM [warn] Command[NaN] Wrong CRC value for the response.
1/3/2022, 11:42:19 AM [warn] Command[75] Wrong CRC value for the response.
1/3/2022, 11:42:20 AM [warn] Command[4] 'DCN' Timeout
1/3/2022, 11:42:20 AM [warn] Command[NaN] Wrong CRC value for the response.
1/3/2022, 11:42:22 AM [warn] Command[75] receivedId is the same as lastReceivedId, ignoring this panel message
1/3/2022, 11:42:25 AM [warn] Command[75] receivedId is the same as lastReceivedId, ignoring this panel message
1/3/2022, 11:42:25 AM [warn] Command[4] 'DCN' Timeout
1/3/2022, 11:42:25 AM [warn] Command[NaN] Wrong CRC value for the response.
1/3/2022, 11:42:28 AM [warn] Command[74] Wrong CRC value for the response.
1/3/2022, 11:42:30 AM [warn] Command[4] 'DCN' Timeout
1/3/2022, 11:42:30 AM [warn] Command[NaN] Wrong CRC value for the response.
1/3/2022, 11:42:31 AM [warn] Command[74] receivedId is the same as lastReceivedId, ignoring this panel message
1/3/2022, 11:42:34 AM [warn] Command[74] receivedId is the same as lastReceivedId, ignoring this panel message
1/3/2022, 11:42:35 AM [warn] Command[4] 'DCN' Timeout
1/3/2022, 11:42:35 AM [warn] Command[NaN] Wrong CRC value for the response.
1/3/2022, 11:42:37 AM [warn] Command[77] Wrong CRC value for the response.
1/3/2022, 11:42:40 AM [warn] Command[77] receivedId is the same as lastReceivedId, ignoring this panel message
1/3/2022, 11:42:40 AM [warn] Command[4] 'DCN' Timeout
1/3/2022, 11:42:40 AM [warn] Command[NaN] Wrong CRC value for the response.
1/3/2022, 11:42:43 AM [warn] Command[77] receivedId is the same as lastReceivedId, ignoring this panel message
1/3/2022, 11:42:45 AM [warn] Command[4] 'DCN' Timeout
1/3/2022, 11:42:45 AM [error] Command[NaN] Too many bad CRC value.
1/3/2022, 11:42:46 AM [error] Command[76] Too many bad CRC value.
1/3/2022, 11:42:49 AM [warn] Command[76] receivedId is the same as lastReceivedId, ignoring this panel message
1/3/2022, 11:42:50 AM [warn] Command[4] 'DCN' Timeout
1/3/2022, 11:42:50 AM [error] Command[NaN] Too many bad CRC value.
1/3/2022, 11:42:52 AM [warn] Command[76] receivedId is the same as lastReceivedId, ignoring this panel message
1/3/2022, 11:42:55 AM [error] Command[71] Too many bad CRC value.
1/3/2022, 11:42:55 AM [warn] Command[4] 'DCN' Timeout
1/3/2022, 11:42:55 AM [error] Command[NaN] Too many bad CRC value.
1/3/2022, 11:42:58 AM [warn] Command[71] receivedId is the same as lastReceivedId, ignoring this panel message
pergolafabio commented 2 years ago

hi @vanackej

thnx!! much appreciated, ill update as soon as you release a new version indeed , looks to run more stable now, i have it running now for 2 days, exported logs, didnt see any error yet

if you release a new version, i do the same test again and provide feedback otherwise i'll open a new one

i will close other tickets now on the other github page

pergolafabio commented 2 years ago

ah, i see you already released it ? 0.3.1 ? or is another version coming?

vanackej commented 2 years ago

Yes I just released it. Very few changes, I just don't try to send commands again when socket is disconnected. Should just fix one of the errors you reported when you tried to disconnect network cable.

pergolafabio commented 2 years ago

perfect, i'll keep you posted

thnx!