Homeworks Plugin Fails on Launch

blairharrison commented 3 years ago

Plugin Fails on Launch

Thank you for building this... I'm very much looking forward to using it. My Lutron dealer quoted me $28k and all I want is to HomeKit enable my system! So find this was a godsend. My issue below...

Problem:

I've installed the Homebridge Lutron Homeworks plugin, but it fails on launch.

I bought and configured a new RPi yesterday, and installed Homebridge. And after upgrading a few things (e.g. Node version, and I did end up with 2 installs of Node, although both are current LTS rev) all worked fine. Registered in HomeKit ok. Browser config tool works fine. Running as service. etc. All good.

Then I installed the Homebridge Lutron Homeworks plugin. It fails on launch (see logs below). While it has failed a couple of times with an error / debug output (e.g. malloc(): invalid size (unsorted), and some error about a double linked list failing?!), most of the time, and currently, it just fails silently.

For example, right now it failed several times with the above malloc() failure, but after it auto-restarted itself a few times (which it's doing now in an endless loop), it now does this...

Plugin seems to load ok...

[4/25/2021, 1:02:18 PM] ---
[4/25/2021, 1:02:18 PM] Loaded plugin: homebridge-lutron-homeworks@0.1.4
[4/25/2021, 1:02:18 PM] Registering platform 'homebridge-lutron-homeworks.LutronHomeworks'
[4/25/2021, 1:02:18 PM] ---

...but then it fails during the Initializing phase...

[4/25/2021, 1:02:18 PM] [Lutron Homeworks] Initializing LutronHomeworks platform...
[4/25/2021, 1:02:18 PM] [HB Supervisor] Homebridge Process Ended. Code: null, Signal: SIGSEGV
[4/25/2021, 1:02:22 PM] [Homebridge UI] Sending SIGKILL to Homebridge
[4/25/2021, 1:02:23 PM] [HB Supervisor] Restarting Homebridge...

I'm pretty sure I installed all dependencies correctly - e.g. serialport, etc. I have also...

Connected RPi via USB <-> RS232 cable
Ensured correct password in Config file (looked up from Link 3 config on Processor)
Verified that I can telnet to the Lutron (both from RPi and other laptop)
Used tio from RPi to connect directly via /dev/ttyUSB01 and got what looks like a valid connection but there's no way to enter password, and no feedback given, I just got this...

pi@homebridgepi:~ $ tio -e /dev/ttyUSB0
[tio 12:58:42] tio v1.32
[tio 12:58:42] Press ctrl-t q to quit
[tio 12:58:42] Connected

Logs:

Here's the Homebridge log from a restart just now...

Loading logs using native method...
File: /var/lib/homebridge/homebridge.log

[4/25/2021, 1:02:15 PM] [Homebridge UI] Homebridge log truncated by admin.
[4/25/2021, 1:02:15 PM] [Homebridge UI] Homebridge restart request received
[4/25/2021, 1:02:15 PM] [Homebridge UI] UI / Bridge settings have not changed; only restarting Homebridge process
[4/25/2021, 1:02:15 PM] [Homebridge UI] Sending SIGTERM to Homebridge
[4/25/2021, 1:02:16 PM] [HB Supervisor] Restarting Homebridge...
[4/25/2021, 1:02:16 PM] [HB Supervisor] Starting Homebridge with extra flags: -I
[4/25/2021, 1:02:16 PM] [HB Supervisor] Started Homebridge v1.3.4 with PID: 29900
Initializing HAP-NodeJS v0.9.4...
[4/25/2021, 1:02:17 PM] Loaded config.json with 0 accessories and 2 platforms.
[4/25/2021, 1:02:17 PM] Loaded 0 cached accessories from cachedAccessories.
[4/25/2021, 1:02:17 PM] ---
[4/25/2021, 1:02:18 PM] Loaded plugin: homebridge-config-ui-x@4.41.0
[4/25/2021, 1:02:18 PM] Registering platform 'homebridge-config-ui-x.config'
[4/25/2021, 1:02:18 PM] ---
[4/25/2021, 1:02:18 PM] Loaded plugin: homebridge-lutron-homeworks@0.1.4
[4/25/2021, 1:02:18 PM] Registering platform 'homebridge-lutron-homeworks.LutronHomeworks'
[4/25/2021, 1:02:18 PM] ---
[4/25/2021, 1:02:18 PM] Loading 2 platforms...
[4/25/2021, 1:02:18 PM] [Config] Initializing config platform...
[4/25/2021, 1:02:18 PM] [Config] Running in Service Mode
[4/25/2021, 1:02:18 PM] [Lutron Homeworks] Initializing LutronHomeworks platform...
[4/25/2021, 1:02:18 PM] [HB Supervisor] Homebridge Process Ended. Code: null, Signal: SIGSEGV
[4/25/2021, 1:02:22 PM] [Homebridge UI] Sending SIGKILL to Homebridge
[4/25/2021, 1:02:23 PM] [HB Supervisor] Restarting Homebridge...
[4/25/2021, 1:02:23 PM] [HB Supervisor] Starting Homebridge with extra flags: -I
[4/25/2021, 1:02:23 PM] [HB Supervisor] Started Homebridge v1.3.4 with PID: 29926
Initializing HAP-NodeJS v0.9.4...
[4/25/2021, 1:02:24 PM] Loaded config.json with 0 accessories and 2 platforms.
[4/25/2021, 1:02:24 PM] Loaded 0 cached accessories from cachedAccessories.
[4/25/2021, 1:02:24 PM] ---
[4/25/2021, 1:02:25 PM] Loaded plugin: homebridge-config-ui-x@4.41.0
[4/25/2021, 1:02:25 PM] Registering platform 'homebridge-config-ui-x.config'
[4/25/2021, 1:02:25 PM] ---
[4/25/2021, 1:02:25 PM] Loaded plugin: homebridge-lutron-homeworks@0.1.4
[4/25/2021, 1:02:25 PM] Registering platform 'homebridge-lutron-homeworks.LutronHomeworks'
[4/25/2021, 1:02:25 PM] ---
[4/25/2021, 1:02:25 PM] Loading 2 platforms...
[4/25/2021, 1:02:25 PM] [Config] Initializing config platform...
[4/25/2021, 1:02:25 PM] [Config] Running in Service Mode
[4/25/2021, 1:02:25 PM] [Lutron Homeworks] Initializing LutronHomeworks platform...
malloc(): invalid size (unsorted)
[4/25/2021, 1:02:25 PM] [HB Supervisor] Homebridge Process Ended. Code: null, Signal: SIGABRT
[4/25/2021, 1:02:30 PM] [HB Supervisor] Restarting Homebridge...
[4/25/2021, 1:02:30 PM] [HB Supervisor] Starting Homebridge with extra flags: -I
[4/25/2021, 1:02:30 PM] [HB Supervisor] Started Homebridge v1.3.4 with PID: 29950
Initializing HAP-NodeJS v0.9.4...
[4/25/2021, 1:02:31 PM] Loaded config.json with 0 accessories and 2 platforms.
[4/25/2021, 1:02:31 PM] Loaded 0 cached accessories from cachedAccessories.
[4/25/2021, 1:02:31 PM] ---
[4/25/2021, 1:02:32 PM] Loaded plugin: homebridge-config-ui-x@4.41.0
[4/25/2021, 1:02:32 PM] Registering platform 'homebridge-config-ui-x.config'
[4/25/2021, 1:02:32 PM] ---
[4/25/2021, 1:02:32 PM] Loaded plugin: homebridge-lutron-homeworks@0.1.4
[4/25/2021, 1:02:32 PM] Registering platform 'homebridge-lutron-homeworks.LutronHomeworks'
[4/25/2021, 1:02:32 PM] ---
[4/25/2021, 1:02:32 PM] Loading 2 platforms...
[4/25/2021, 1:02:32 PM] [Config] Initializing config platform...
[4/25/2021, 1:02:32 PM] [Config] Running in Service Mode
[4/25/2021, 1:02:32 PM] [Lutron Homeworks] Initializing LutronHomeworks platform...
[4/25/2021, 1:02:32 PM] [HB Supervisor] Homebridge Process Ended. Code: null, Signal: SIGSEGV

...then it just keeps going in the load - fail - restart loop ad infinitum.

Plugin Config:

{
    "bridge": {
        "name": "Homebridge 56C9",
        "username": "______",
        "port": 51633,
        "pin": "XXX-XX-XXX"
    },
    "accessories": [],
    "platforms": [
        {
            "name": "Config",
            "port": 8581,
            "platform": "config"
        },
        {
            "name": "Lutron Homeworks",
            "serialPath": "/dev/ttyUSB0",
            "loginRequired": true,
            "password": "__________",
            "defaultFadeTime": 1,
            "platform": "LutronHomeworks"
        }
    ]
}

Screenshots:

None applicable.

Environment:

Plugin Version: homebridge-lutron-homeworks v0.1.4
Homebridge Version: homebridge-config-ui-x v4.41.0
Node.js Version: v14.16.1
NPM Version: v6.14.12
Operating System: Linux homebridgepi 5.10.17-v7l+ #1403 SMP Mon Feb 22 11:33:35 GMT 2021 armv7l GNU/Linux

cptechie commented 3 years ago

Hey there! This seems like a case of the USB modem not being able to be found or connected to due to permissions.

Can you try the following: https://askubuntu.com/questions/112568/how-do-i-allow-a-non-default-user-to-use-serial-device-ttyusb0

Afterwards, see if you can connect to the serial device directly from the terminal using minicom. You should be able to send the command RST and receive the current system time back from the Homeworks system.

https://openmaniak.com/minicom.php

The link above should help you with getting minicom going.

blairharrison commented 3 years ago

Thank you so much for responding! I will try that and let you know...

cptechie commented 3 years ago

Also can you put your homebridge in debug mode and post the log please? I might be able to confirm if my hunch is correct by its output.

blairharrison commented 3 years ago

I have just...

Installed minicom
Verified that I have "active serial ports"

pi@homebridgepi:/dev $ sudo dmesg | grep tty
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=480 bcm2708_fb.fbheight=320 bcm2708_fb.fbswap=1 smsc95xx.macaddr=DC:A6:32:E9:27:A5 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=tty1 console=ttyAMA0,115200 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline rootwait fbcon=map:10 fbcon=font:ProFont6x11 logo.nologo
[    0.001836] printk: console [tty1] enabled
[    1.548895] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 36, base_baud = 0) is a PL011 rev2
[    2.808804] printk: console [ttyAMA0] enabled
[    2.832185] fe215040.serial: ttyS0 at MMIO 0xfe215040 (irq = 38, base_baud = 62500000) is a 16550
[    8.148299] usb 1-1.2: FTDI USB Serial Device converter now attached to ttyUSB0

Verified that my user "pi" is a member of group "dialout"

pi@homebridgepi:/dev $ sudo adduser pi dialout
The user `pi' is already a member of `dialout'.

Verified permissions are good on ttyUSB0

pi@homebridgepi:/dev $ ls -al | grep ttyUSB0
crw-rw----   1 root dialout 188,   0 Apr 27 09:28 ttyUSB0

Launched minicom... but got this... and it looks like it's not doing anything
How do I submit the "RST" command, for example (sorry for not knowing this)?

Welcome to minicom 2.7.1

OPTIONS: I18n 
Compiled on Aug 13 2017, 15:25:34.
Port /dev/ttyUSB0, 09:28:00

Press CTRL-A Z for help on special keys

Next up... I had already enabled debugging... I will post a log next...

blairharrison commented 3 years ago

Homebridge "Homebridge Debug Mode -D" enabled
I have not added anything to the DEBUG environment variable (needed?)

Here's the log...

Note that there's a single device listed in the logs... I added this manually to the config file to see if it made a difference... as I suspected it may need at least one device to launch (even though the docs say it auto-discovers devices). It made no difference to the behavior.

As you can see it keeps restarting itself in a loop...

[4/27/2021, 9:47:03 AM] [HB Supervisor] Restarting Homebridge...
[4/27/2021, 9:47:03 AM] [HB Supervisor] Starting Homebridge with extra flags: -I -D
[4/27/2021, 9:47:03 AM] [HB Supervisor] Started Homebridge v1.3.4 with PID: 9071
Initializing HAP-NodeJS v0.9.4...
[4/27/2021, 9:47:04 AM] Loaded config.json with 0 accessories and 2 platforms.
[4/27/2021, 9:47:04 AM] Loaded 0 cached accessories from cachedAccessories.
[4/27/2021, 9:47:04 AM] ---
[4/27/2021, 9:47:05 AM] Loaded plugin: homebridge-config-ui-x@4.41.1
[4/27/2021, 9:47:05 AM] Registering platform 'homebridge-config-ui-x.config'
[4/27/2021, 9:47:05 AM] ---
[4/27/2021, 9:47:05 AM] Loaded plugin: homebridge-lutron-homeworks@0.1.4
[4/27/2021, 9:47:05 AM] Registering platform 'homebridge-lutron-homeworks.LutronHomeworks'
[4/27/2021, 9:47:05 AM] ---
[4/27/2021, 9:47:05 AM] Loading 2 platforms...
[4/27/2021, 9:47:05 AM] [Config] Initializing config platform...
[4/27/2021, 9:47:05 AM] [Config] Running in Service Mode
[4/27/2021, 9:47:05 AM] [Lutron Homeworks] Initializing LutronHomeworks platform...
[4/27/2021, 9:47:05 AM] [Lutron Homeworks] Finished initializing platform: Lutron Homeworks
[4/27/2021, 9:47:05 AM] [Lutron Homeworks] Found name Kitchen in customDevice 01:04:01:01:03
[4/27/2021, 9:47:05 AM] [HB Supervisor] Homebridge Process Ended. Code: null, Signal: SIGSEGV
[4/27/2021, 9:47:10 AM] [HB Supervisor] Restarting Homebridge...
[4/27/2021, 9:47:10 AM] [HB Supervisor] Starting Homebridge with extra flags: -I -D
[4/27/2021, 9:47:10 AM] [HB Supervisor] Started Homebridge v1.3.4 with PID: 9095
Initializing HAP-NodeJS v0.9.4...
[4/27/2021, 9:47:11 AM] Loaded config.json with 0 accessories and 2 platforms.
[4/27/2021, 9:47:11 AM] Loaded 0 cached accessories from cachedAccessories.
[4/27/2021, 9:47:11 AM] ---
[4/27/2021, 9:47:12 AM] Loaded plugin: homebridge-config-ui-x@4.41.1
[4/27/2021, 9:47:12 AM] Registering platform 'homebridge-config-ui-x.config'
[4/27/2021, 9:47:12 AM] ---
[4/27/2021, 9:47:12 AM] Loaded plugin: homebridge-lutron-homeworks@0.1.4
[4/27/2021, 9:47:12 AM] Registering platform 'homebridge-lutron-homeworks.LutronHomeworks'
[4/27/2021, 9:47:12 AM] ---
[4/27/2021, 9:47:12 AM] Loading 2 platforms...
[4/27/2021, 9:47:12 AM] [Config] Initializing config platform...
[4/27/2021, 9:47:12 AM] [Config] Running in Service Mode
[4/27/2021, 9:47:12 AM] [Lutron Homeworks] Initializing LutronHomeworks platform...
[4/27/2021, 9:47:12 AM] [Lutron Homeworks] Finished initializing platform: Lutron Homeworks
[4/27/2021, 9:47:12 AM] [Lutron Homeworks] Found name Kitchen in customDevice 01:04:01:01:03
[4/27/2021, 9:47:12 AM] [HB Supervisor] Homebridge Process Ended. Code: null, Signal: SIGSEGV
[4/27/2021, 9:47:17 AM] [HB Supervisor] Restarting Homebridge...
[4/27/2021, 9:47:17 AM] [HB Supervisor] Starting Homebridge with extra flags: -I -D
[4/27/2021, 9:47:17 AM] [HB Supervisor] Started Homebridge v1.3.4 with PID: 9119
Initializing HAP-NodeJS v0.9.4...
[4/27/2021, 9:47:18 AM] Loaded config.json with 0 accessories and 2 platforms.
[4/27/2021, 9:47:18 AM] Loaded 0 cached accessories from cachedAccessories.
[4/27/2021, 9:47:18 AM] ---
[4/27/2021, 9:47:19 AM] Loaded plugin: homebridge-config-ui-x@4.41.1
[4/27/2021, 9:47:19 AM] Registering platform 'homebridge-config-ui-x.config'
[4/27/2021, 9:47:19 AM] ---
[4/27/2021, 9:47:19 AM] Loaded plugin: homebridge-lutron-homeworks@0.1.4
[4/27/2021, 9:47:19 AM] Registering platform 'homebridge-lutron-homeworks.LutronHomeworks'
[4/27/2021, 9:47:19 AM] ---
[4/27/2021, 9:47:19 AM] Loading 2 platforms...
[4/27/2021, 9:47:19 AM] [Config] Initializing config platform...
[4/27/2021, 9:47:19 AM] [Config] Running in Service Mode
[4/27/2021, 9:47:19 AM] [Lutron Homeworks] Initializing LutronHomeworks platform...
[4/27/2021, 9:47:19 AM] [Lutron Homeworks] Finished initializing platform: Lutron Homeworks
[4/27/2021, 9:47:19 AM] [Lutron Homeworks] Found name Kitchen in customDevice 01:04:01:01:03
[4/27/2021, 9:47:19 AM] [HB Supervisor] Homebridge Process Ended. Code: null, Signal: SIGSEGV

cptechie commented 3 years ago

Unfortunately minicom is not the most intuitive piece of software. See if you can follow the steps below to connect to Homeworks and retrieve the system time.

Launch minicom in setup mode using $ minicom -s
Go to Serial port setup
- Change Serial Device to the path of your modem
  - most likely /dev/ttyUSB0
- Press the return key twice on the keyboard to get back to the configuration screen
Go to Screen and keyboard
- Set Add linefeed to Yes
- Set Local echo to Yes
- Press the return key once on the keyboard to get back to the configuration screen
Select Save setup as dfl
Select Exit from Minicom

Minicom should now be configured and we can now test if you can actually connect to Homeworks.

Launch minicom using $ minicom
You should see the below

Welcome to minicom 2.7.1

OPTIONS: I18n 
Compiled on Jun 10 2019, 15:09:39.
Port /dev/ttyUSB0, 17:08:13

Press CTRL-A Z for help on special keys

You should now be able to type the command rst and it the final output should look like below
```
Welcome to minicom 2.7.1
```

OPTIONS: I18n Compiled on Jun 10 2019, 15:09:39. Port /dev/ttyUSB0, 17:08:13

Press CTRL-A Z for help on special keys

rst

Processor Time: 17:11


4. To exit minicom, Press `Ctrl+A` followed by `Z`, then `X` and finally `return`

cptechie commented 3 years ago

Also the permission for my /dev/ttyUSB0 device is 666.

If you are not able to get the system time from above, try $ sudo chmod 666 /dev/ttyUSB0

blairharrison commented 3 years ago

I went through all the steps but just get this... no response...

Welcome to minicom 2.7.1

OPTIONS: I18n 
Compiled on Aug 13 2017, 15:25:34.
Port /dev/ttyUSB0

Press CTRL-A Z for help on special keys

rst

Does this mean it's not connecting to the Lutron?

blairharrison commented 3 years ago

I set permission on /dev/ttyUSB0 as you suggested

blairharrison commented 3 years ago

I wonder if I've got the wrong cable? I bought this one... https://www.amazon.com/gp/product/B08Q86PFV1/ref=ppx_yo_dt_b_asin_title_o01_s00?ie=UTF8&psc=1

cptechie commented 3 years ago

I wonder if I've got the wrong cable? I bought this one... https://www.amazon.com/gp/product/B08Q86PFV1/ref=ppx_yo_dt_b_asin_title_o01_s00?ie=UTF8&psc=1

I have personally have tested with a serial cable with a PL2303 chipset and your's is FTDI, but this shouldn't be an issue. Actually a quick google of PL2303 vs FTDI shows that FTDI is superior. Either way, I don't think this should be an issue.

I went through all the steps but just get this... no response...
Welcome to minicom 2.7.1

OPTIONS: I18n 
Compiled on Aug 13 2017, 15:25:34.
Port /dev/ttyUSB0

Press CTRL-A Z for help on special keys

rst
Does this mean it's not connecting to the Lutron?

Hmm, you are not getting a response back.

Can you report the response back from the LOGIN command in minicom? If you think that you have a password then the command would be LOGIN, your_password.

Here is the response I had received:

login, jetski

RS232 port 01:03:001 already logged in. Login Successful

blairharrison commented 3 years ago

Nothing.

I wonder if I need to change RS232 / serial port info... I've got access to the full Homeworks Windows application, so I can get in and investigate the serial port settings... although I assume all key info (baud rate, parity, etc.) are all done during the initial handshake?

blairharrison commented 3 years ago

Lutron says the RS232 link is up...

cptechie commented 3 years ago

Nothing.

I wonder if I need to change RS232 / serial port info... I've got access to the full Homeworks Windows application, so I can get in and investigate the serial port settings... although I assume all key info (baud rate, parity, etc.) are all done during the initial handshake?

Actually I have hardcoded the baud rate to be 115200 as that’s what the system I developed for was using and I didn’t have the foresight at the time to make that into a configuration variable instead.

It’s kinda cool that you have access to the full Windows application. My experience with the Homeworks system has been limited to the serial port and the WebUI for the keypads.

Are you able to see its configured baud rate?

blairharrison commented 3 years ago

just found this...

HomeWorks Interactive processors require the use of a standard 9-pin DB9 serial cable for communications with external equipment. This cable must be a 9-wire, straight through cable, not a 3-wire cable.
The available baud rates are 9600, 19200, 38400, 57600, and 115,200 baud. When dip switch #1 on S2 is up the baud rate is 9600 baud, and when it is down the baud rate is set to the user setting according to the SETBAUD command - The HomeWorks Interactive processors use hardware handshaking for flow control by default. Software handshaking will not work. The hardware handshaking may be disabled using the SETHAND command. If hardware handshaking is disabled, Lutron recommends using a low baud rate to avoid buffer overflow problems.
Other communication settings include, 8 data bits, 1 stop bit, and no parity bit

blairharrison commented 3 years ago

SUCCESS!!! I set the baud rate to 9600 in minicom and boom...

Welcome to minicom 2.7.1

OPTIONS: I18n 
Compiled on Aug 13 2017, 15:25:34.
Port /dev/ttyUSB0, 12:00:49

Press CTRL-A Z for help on special keys

rst

Processor Time: 12:01

cptechie commented 3 years ago

Awesome! Can you confirm that you can login as well?

In the mean time, I am going to update the code to have an option for baud rate.

blairharrison commented 3 years ago

yes! RS232 port 01:03:001 already logged in. Login Successful

cptechie commented 3 years ago

Just published an update. You should be able to add "baudRate": 9600 into config.json

blairharrison commented 3 years ago

Great! Thank you so much... will try this now...

blairharrison commented 3 years ago

I assume you meant "baud" in the release notes... you entered "buad" (typo)

cptechie commented 3 years ago

Oops, yup. It is definitely baudRate.

blairharrison commented 3 years ago

It's all working!!! Just playing with it now... thank you so much for all your help :)

cptechie commented 3 years ago

Great to hear!

I'm going to go ahead and close this issue. Feel free to open another issue if you run into anything else or have any requests.

cptechie / homebridge-lutron-homeworks

Homeworks Plugin Fails on Launch #6

Plugin Fails on Launch