Altsteon loses device definitions

Salmoides · December 8, 2013, 6:32pm

I’m trying to get Altsteon to work more than once on VeraLite through a PowerLinc 2413U with a single ToggleLinc 2466S and a FanLinc 2475F. I’m using the development version of Altsteon (20 Oct). Following the instructions I can get the PLM installed and both devices. Upon a Reload, the two additional FanLinc devices are created and I can see everything as I would expect.

When I act on the devices through the GUI the first time, all works well. But after that, nada. Upon reboot, the PLM sees the devices, but they are no longer recognized. I’ve done this twice, so it’s repeatable. Log parts are shown below. At about 11:49, I command the fan to high (speed level 3) and the light to full on (light level 100%). Both work successfully. But immediately after that, commands to set the fan speed to level 1 (low) fail and I get no response from the devices.

After I was done banging my head on the desk, I executed a reboot. Vera came back and a list command in altsteon_cli shows that both the ToggleLinc and the FanLinc are now unknown devices to the PLM. Also, it appears there’s a parsing problem where it says “plm is an unknown device!” and “end is an unknown device!”

Any ideas where I’ve gone wrong or what I can do? I’m at a loss. Thanks.

root:~# grep “luup_log:72” /var/log/cmh/LuaUPnP.log
50 12/08/13 11:35:55.771 luup_log:72: Insteon PLM, Device #72 starting. <0x2be93680>
50 12/08/13 11:35:55.772 luup_log:72: Running Network Attached I_InsteonPlm.xml on 127.0.0.1 <0x2be93680>
50 12/08/13 11:35:55.872 luup_log:72: Sending (startup_plm) : start_tagging
50 12/08/13 11:35:55.874 luup_log:72: Sending (startup_plm) : del_untagged_devices
50 12/08/13 11:40:46.783 luup_log:72: Insteon PLM, Device #72 starting. <0x2bdbf680>
50 12/08/13 11:40:46.784 luup_log:72: Running Network Attached I_InsteonPlm.xml on 127.0.0.1 <0x2bdbf680>
50 12/08/13 11:40:46.885 luup_log:72: Sending (startup_plm) : start_tagging
50 12/08/13 11:40:46.886 luup_log:72: Found Child ID: 73 AltID: 1d.18.e3 <0x2bdbf680>
50 12/08/13 11:40:46.886 luup_log:72: Sending (startup_plm) : add_device 1d.18.e3
50 12/08/13 11:40:46.887 luup_log:72: Found Child ID: 74 AltID: 23.11.9a <0x2bdbf680>
50 12/08/13 11:40:46.888 luup_log:72: Sending (startup_plm) : add_device 23.11.9a
50 12/08/13 11:40:46.890 luup_log:72: Sending (startup_plm) : del_untagged_devices
50 12/08/13 11:40:47.270 luup_log:72: Parsing : 1d.18.e3:001C,01,02 - Insteon version 2. <0x2f3bf680>
50 12/08/13 11:40:47.271 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2f3bf680>
50 12/08/13 11:40:47.271 luup_log:72: Device : 73 Protocol Version : 2 <0x2f3bf680>
50 12/08/13 11:40:48.220 luup_log:72: Parsing : 23.11.9a:001C,02,02 - Insteon version 2. <0x2f3bf680>
50 12/08/13 11:40:48.221 luup_log:72: Sending to child id 74 (23.11.9a) <0x2f3bf680>
50 12/08/13 11:40:48.221 luup_log:72: Device : 74 Protocol Version : 2 <0x2f3bf680>
50 12/08/13 11:40:49.472 luup_log:72: Parsing : 1d.18.e3:003D,02 - Device added. (0x02) <0x2f3bf680>
50 12/08/13 11:40:49.472 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2f3bf680>
50 12/08/13 11:40:49.473 luup_log:72: Sending (core) : 1d.18.e3 info
50 12/08/13 11:40:49.474 luup_log:72: Parsing : 1d.18.e3:003D,02 - Device added. (0x02) <0x2f3bf680>
50 12/08/13 11:40:49.475 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2f3bf680>
50 12/08/13 11:40:49.475 luup_log:72: Sending (core) : 1d.18.e3 info
50 12/08/13 11:40:49.499 luup_log:72: Parsing : 1d.18.e3:0007,FF,02,1A,41 - DevCat : 02 SubCat : 1A Ver : 41 <0x2f3bf680>
50 12/08/13 11:40:49.500 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2f3bf680>
50 12/08/13 11:40:49.500 luup_log:72: Device : 73 DevCat : 2 SubCat : 26 DevVer : 65 <0x2f3bf680>
50 12/08/13 11:40:49.503 luup_log:72: Sending (setLongName) : “1d.18.e3” set_long_name “Front Porch Light” <0x2f3bf680>
50 12/08/13 11:40:49.505 luup_log:72: Sending (relay,start) : “1d.18.e3” get_devopts
50 12/08/13 11:40:49.508 luup_log:72: Parsing : 1d.18.e3:0007,FF,02,1A,41 - DevCat : 02 SubCat : 1A Ver : 41 <0x2f3bf680>
50 12/08/13 11:40:49.509 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2f3bf680>
50 12/08/13 11:40:49.509 luup_log:72: Device : 73 DevCat : 2 SubCat : 26 DevVer : 65 <0x2f3bf680>
50 12/08/13 11:40:49.511 luup_log:72: Sending (setLongName) : “1d.18.e3” set_long_name “Front Porch Light” <0x2f3bf680>
50 12/08/13 11:40:49.512 luup_log:72: Sending (relay,start) : “1d.18.e3” get_devopts
50 12/08/13 11:40:50.280 luup_log:72: Parsing : 1d.18.e3:001C,01,02 - Insteon version 2. <0x2f3bf680>
50 12/08/13 11:40:50.281 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2f3bf680>
50 12/08/13 11:40:50.281 luup_log:72: Device : 73 Protocol Version : 2 <0x2f3bf680>
50 12/08/13 11:40:51.422 luup_log:72: Parsing : 23.11.9a:003D,02 - Device added. (0x01) <0x2f3bf680>
50 12/08/13 11:40:51.422 luup_log:72: Sending to child id 74 (23.11.9a) <0x2f3bf680>
50 12/08/13 11:40:51.423 luup_log:72: Sending (core) : 23.11.9a info
50 12/08/13 11:40:51.426 luup_log:72: Parsing : 23.11.9a:0007,FF,01,2E,41 - DevCat : 01 SubCat : 2E Ver : 41 <0x2f3bf680>
50 12/08/13 11:40:51.427 luup_log:72: Sending to child id 74 (23.11.9a) <0x2f3bf680>
50 12/08/13 11:40:51.427 luup_log:72: Device : 74 DevCat : 1 SubCat : 46 DevVer : 65 <0x2f3bf680>
50 12/08/13 11:40:51.433 luup_log:72: Sending (setLongName) : “23.11.9a” set_long_name “Living Room Fan/Light” <0x2f3bf680>
50 12/08/13 11:41:11.607 luup_log:72: Insteon PLM, Device #72 starting. <0x2b475680>
50 12/08/13 11:41:11.608 luup_log:72: Running Network Attached I_InsteonPlm.xml on 127.0.0.1 <0x2b475680>
50 12/08/13 11:41:11.618 luup_log:72: Sending (startup_plm) : start_tagging
50 12/08/13 11:41:11.620 luup_log:72: Found Child ID: 73 AltID: 1d.18.e3 <0x2b475680>
50 12/08/13 11:41:11.620 luup_log:72: Sending (startup_plm) : add_device 1d.18.e3
50 12/08/13 11:41:11.623 luup_log:72: Found Child ID: 74 AltID: 23.11.9a <0x2b475680>
50 12/08/13 11:41:11.623 luup_log:72: Sending (startup_plm) : add_device 23.11.9a
50 12/08/13 11:41:11.625 luup_log:72: Sending (startup_plm) : del_untagged_devices
50 12/08/13 11:41:11.669 luup_log:72: Parsing : 1d.18.e3:003D,02 - Device added. (exists case) LEAK this:36864 start:1896448 to 0x1445000 <0x2de75680>
50 12/08/13 11:41:11.670 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2de75680>
50 12/08/13 11:41:11.670 luup_log:72: Sending (core) : 1d.18.e3 info
50 12/08/13 11:41:11.672 luup_log:72: Parsing : 23.11.9a:003D,02 - Device added. (exists case) <0x2de75680>
50 12/08/13 11:41:11.673 luup_log:72: Sending to child id 74 (23.11.9a) <0x2de75680>
50 12/08/13 11:41:11.673 luup_log:72: Sending (core) : 23.11.9a info
50 12/08/13 11:41:11.676 luup_log:72: Parsing : 1d.18.e3:0007,01,02,1A,41 - DevCat : 02 SubCat : 1A Ver : 41 <0x2de75680>
50 12/08/13 11:41:11.677 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2de75680>
50 12/08/13 11:41:11.678 luup_log:72: Device : 73 DevCat : 2 SubCat : 26 DevVer : 65 <0x2de75680>
50 12/08/13 11:41:11.691 luup_log:72: Sending (setLongName) : “1d.18.e3” set_long_name “Front Porch Light” <0x2de75680>
50 12/08/13 11:41:11.692 luup_log:72: Sending (relay,start) : “1d.18.e3” get_devopts
50 12/08/13 11:41:11.695 luup_log:72: Parsing : 23.11.9a:0007,02,01,2E,41 - DevCat : 01 SubCat : 2E Ver : 41 <0x2de75680>
50 12/08/13 11:41:11.696 luup_log:72: Sending to child id 74 (23.11.9a) <0x2de75680>
50 12/08/13 11:41:11.696 luup_log:72: Device : 74 DevCat : 1 SubCat : 46 DevVer : 65 <0x2de75680>
50 12/08/13 11:41:11.698 luup_log:72: Sending (setLongName) : “23.11.9a” set_long_name “Living Room Fan/Light” <0x2de75680>
50 12/08/13 11:41:11.710 luup_log:72: Found Child ID: 75 AltID: 23.11.9a_Light Looking for : 23.11.9a_(fan/switch) <0x2de75680>
50 12/08/13 11:41:11.711 luup_log:72: ************ Switch Id : 75 <0x2de75680>
50 12/08/13 11:41:11.711 luup_log:72: Found Child ID: 76 AltID: 23.11.9a_Fan Looking for : 23.11.9a_(fan/switch) <0x2de75680>
50 12/08/13 11:41:11.712 luup_log:72: *********** Fan Id : 76 <0x2de75680>
50 12/08/13 11:41:12.321 luup_log:72: Parsing : 1d.18.e3:001A,01 - Program lock is off. <0x2de75680>
50 12/08/13 11:41:12.322 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2de75680>
50 12/08/13 11:41:12.370 luup_log:72: Parsing : 1d.18.e3:0018,01 - LED off during transmit. <0x2de75680>
50 12/08/13 11:41:12.371 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2de75680>
50 12/08/13 11:41:12.372 luup_log:72: Parsing : 1d.18.e3:0016,01 - Resume dim disabled. <0x2de75680>
50 12/08/13 11:41:12.373 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2de75680>
50 12/08/13 11:41:12.374 luup_log:72: Parsing : 1d.18.e3:0010,01 - LED is on. <0x2de75680>
50 12/08/13 11:41:12.375 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2de75680>
50 12/08/13 11:41:12.377 luup_log:72: Parsing : 1d.18.e3:001E,01 - Load sense is on. <0x2de75680>
50 12/08/13 11:41:12.377 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2de75680>
50 12/08/13 11:46:51.681 luup_log:72: Parsing : 1d.18.e3:0009,01,00 - 1d.18.e3 button/group 0 is off. <0x2de75680>
50 12/08/13 11:46:51.681 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2de75680>
50 12/08/13 11:49:39.401 luup_log:72: Sending (fanlinc,speed) : “23.11.9a” fan_state 3
50 12/08/13 11:49:40.051 luup_log:72: Parsing : 23.11.9a:0057,02,03 - 23.11.9a fan speed is high. <0x2de75680>
50 12/08/13 11:49:40.051 luup_log:72: Sending to child id 74 (23.11.9a) <0x2de75680>
50 12/08/13 11:49:40.052 luup_log:72: Fan speed : 03 <0x2de75680>
50 12/08/13 11:49:51.108 luup_log:72: Setting dimmer to 100 <0x2eecd680>
50 12/08/13 11:49:51.108 luup_log:72: Sending (setloadleveltarget) : “23.11.9a” instant_dim 100
50 12/08/13 11:49:51.831 luup_log:72: Parsing : 23.11.9a:0024,02,FE - Light brightness is 254. <0x2de75680>
50 12/08/13 11:49:51.831 luup_log:72: Sending to child id 74 (23.11.9a) <0x2de75680>
50 12/08/13 11:50:14.952 luup_log:72: Sending (fanlinc,speed) : “23.11.9a” fan_state 1
50 12/08/13 11:50:25.698 luup_log:72: Sending (fanlinc,speed) : “23.11.9a” fan_state 1
50 12/08/13 11:51:00.281 luup_log:72: Sending (toggleswitch) : “1d.18.e3” on
50 12/08/13 11:51:12.813 luup_log:72: Parsing : 1d.18.e3:0046,01,02,1A,00,1D,18,E3 - 1d.18.e3 (DevCat : 2 SubCat : 26 Hidden : 0 Addr : 1D.18.E3) <0x2de75680>
50 12/08/13 11:51:12.814 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2de75680>
50 12/08/13 11:51:12.816 luup_log:72: Parsing : 23.11.9a:0046,02,01,2E,00,23,11,9A - 23.11.9a (DevCat : 1 SubCat : 46 Hidden : 0 Addr : 23.11.9A) <0x2de75680>
50 12/08/13 11:51:12.817 luup_log:72: Sending to child id 74 (23.11.9a) <0x2de75680>
50 12/08/13 11:51:12.820 luup_log:72: Parsing : plm:0046,02,03,15,1,1C,F6,E0 - plm (DevCat : 3 SubCat : 21 Hidden : 1 Addr : 1C.F6.E0) <0x2de75680>
50 12/08/13 11:51:12.821 luup_log:72: plm is an unknown device! <0x2de75680>
50 12/08/13 11:51:12.823 luup_log:72: Parsing : end:004E,02 - End of list. <0x2de75680>
50 12/08/13 11:51:12.824 luup_log:72: end is an unknown device! <0x2de75680>
50 12/08/13 11:51:20.122 luup_log:72: Sending (fanlinc,speed) : “23.11.9a” fan_state 1
50 12/08/13 11:51:42.160 luup_log:72: Sending (fanlinc,speed) : “23.11.9a” fan_state 1
50 12/08/13 11:54:19.377 luup_log:72: Sending (fanlinc,speed) : “23.11.9a” fan_state 1
50 12/08/13 11:54:24.364 luup_log:72: Sending (fanlinc,speed) : “23.11.9a” fan_state 1

root:~# grep “luup_log:72” /var/log/cmh/LuaUPnP.log
50 12/08/13 12:02:13.455 luup_log:72: Insteon PLM, Device #72 starting. <0x2bce1680>
50 12/08/13 12:02:13.456 luup_log:72: Running Network Attached I_InsteonPlm.xml on 127.0.0.1 <0x2bce1680>
50 12/08/13 12:02:13.557 luup_log:72: Sending (startup_plm) : start_tagging
50 12/08/13 12:02:13.558 luup_log:72: Found Child ID: 73 AltID: 1d.18.e3 <0x2bce1680>
50 12/08/13 12:02:13.558 luup_log:72: Sending (startup_plm) : add_device 1d.18.e3
50 12/08/13 12:02:13.559 luup_log:72: Found Child ID: 74 AltID: 23.11.9a <0x2bce1680>
50 12/08/13 12:02:13.560 luup_log:72: Sending (startup_plm) : add_device 23.11.9a
50 12/08/13 12:02:13.561 luup_log:72: Sending (startup_plm) : del_untagged_devices
50 12/08/13 12:04:16.368 luup_log:72: Parsing : 1d.18.e3:0046,FF,FF,FF,00,1D,18,E3 - 1d.18.e3 (DevCat : 255 SubCat : 255 Hidden : 0 Addr : 1D.18.E3) <0x2f0e1680>
50 12/08/13 12:04:16.369 luup_log:72: Sending to child id 73 (1d.18.e3) <0x2f0e1680>
50 12/08/13 12:04:16.372 luup_log:72: Parsing : 23.11.9a:0046,FF,FF,FF,00,23,11,9A - 23.11.9a (DevCat : 255 SubCat : 255 Hidden : 0 Addr : 23.11.9A) <0x2f0e1680>
50 12/08/13 12:04:16.373 luup_log:72: Sending to child id 74 (23.11.9a) <0x2f0e1680>
50 12/08/13 12:04:16.376 luup_log:72: Parsing : plm:0046,02,03,15,1,1C,F6,E0 - plm (DevCat : 3 SubCat : 21 Hidden : 1 Addr : 1C.F6.E0) <0x2f0e1680>
50 12/08/13 12:04:16.377 luup_log:72: plm is an unknown device! <0x2f0e1680>
50 12/08/13 12:04:16.378 luup_log:72: Parsing : end:004E,02 - End of list. <0x2f0e1680>
50 12/08/13 12:04:16.379 luup_log:72: end is an unknown device! <0x2f0e1680>

PurdueGuy · December 8, 2013, 6:39pm

You are doing a full Vera reboot/power cycle? The startup lua starts the Altsteon daemon, right?

Any time the daemon is restarted manually, you need to restart LUUP as well.

If the daemon can’t figure out the device category and subcategory, and everything is started properly, it looks like a communication issue.

From the cli, can you do a “aa.bb.cc poll” and post the results?

Salmoides · December 8, 2013, 7:44pm

I did a reboot at the command line. The startup commands for lua are defined as per the documentation, so the daemon is starting up as required.

My ignorance of Insteon is showing when I ask whether these devices are going to sleep. I ask because I can restart the daemon with debugging enabled and I see this:

[TRACE] [12/8/2013 - 13:17:42] - **** Polling device ‘1d.18.e3’.
[TRACE] [12/8/2013 - 13:17:42] - Adding : 02621D18E30F1900. Multi = false
[TRACE] [12/8/2013 - 13:17:42] - Queued poll request for 1d.18.e3
[TRACE] [12/8/2013 - 13:17:42] - Next poll in 600 second(s).

If I ping the device, nothing returns immediately, but after a while I finally see activity:

Cmd : 23.11.9a ping
23.11.9a:0024,02,00 - Light brightness is 0.

23.11.9a:0057,02,01 - Fan speed is low.

1d.18.e3:0008,01,FF - 1d.18.e3 button/group 255 is on.

23.11.9a:0057,02,03 - 23.11.9a fan speed is high.

23.11.9a:001D,02 - Ping response.

Is there a parameter I need to set to wake these sleepy babies?

Thanks, PurdueGuy.

joey52685 · December 9, 2013, 2:15pm

I have found that you can easily find broken/one-way links by connecting the plm to a computer and using the HouseLinc software. It sounds like issues I was having when switches weren’t linked properly.

http://www.smarthome.com/houselinc.html

Salmoides · December 13, 2013, 10:17pm

My apologies for not thanking you sooner. I’m a weekend warrior with Vera which I have controlling my cabin in the woods.

I’ve returned today and rebooted Vera just for grins. Still no Altsteon control. Logged in, “plm link_new_device” to both of the switch and the FanLinc and the world is happy again. The same device definitions in the UI work. All seems fine. I’m fairly confident the communications are not an issue given that the fanlinc is less than 10 ft away from the PLM. I suspect sometime this weekend the linkage will break again. We’ll see.

PurdueGuy · December 16, 2013, 7:26pm

One time I had the PLM randomly lose all my links, but no other device lost its link to the PLM. That was after a power outage, but I don’t know when it happened, so I can’t say one was related to the other.

thierman · January 18, 2014, 9:52pm

Hi, I’m hoping for some help with Alsteon version 0.08. and my IOLInc module/sensor that I’m using to monitor/control the garage door.

Everything is working pretty well. I have a keypad linc linked to the IOLinc. When the door is open the keypad linc light goes on, when the door is closed the keypad linc goes off.

I have a light in the kitchen being controlled by Vera, in this case it’s also an insteon light but is NOT linked to the Garage door.

I have a scene that turns on the light when the door is opened. (This works) but when the door closes the light does not turn off till the next time the Vera polls the IOLINC, at which time it turns off.

Also, I have triggers setup. They trigger when the door is opened, and message me… Unfortunately, they continue to message me every 10 minutes at the normal polling interval. This mean I can only setup a message to tell me when the door has been opened, and not so much when the door is closed as I get endless messages all day long about the door being closed.

I’m curious, what have I got wrong here…

Here is a copy of my logs, I edited out some of the other devices, profile etc. And bare in mind this log starts AFTER the door has been open for a while. Seemed I used the cli and my logs stopped so I had to restart the cmh…

In anycase… Here is the log, with my comments:

Edgaronline · February 6, 2014, 4:19am

Hi All,

I am seeing the SAME thing that Salmoides is seeing. THe devices can be added and are there…then they are gone.

so in order i can continue to reproduce this:

reboot my Vera 3
go in via SSH
Add a device
link it with alsteon_cli
control the device
reboot
go back in to Vera via SSH
poll. Unkown
(I get the plm[dev number]Lua Engine Failed to Load error on the UI)

The plm is receiving just fine as I am in a room with a motion sensor and altsteon errors when i trip it:
'Unable to locate device . Ignoring result.

I started with a factory reset. I am running the DEV, but had the same result with 08.

Is my PLM going bad? Anything else I can check? really trying to narrow this down. I think comms are just fine…

I am going to mess around with Houslinc a bit to see if i can reproduce similar symptoms…to see if the PLM is actually keeping devices or not.

My PLM is about 1.5 years old…could be going bad…the track record on the PLMs is poor…

Thanks in advance for any help!

v/r

Kevin