From: George C. <ge...@fe...> - 2014-01-18 20:15:32
|
Hi all, I've re-applied the TCP patch against the latest Insteon_PLM code. Basic functionality works well. I'm able to control devices via misterhouse and the PLM. This includes both Insteon and X10 devices. However some device requests fail with retries. I suspect that it's an issue in the IP changes and receiving information from the device. I wonder if the original author ever got these functions working for IP, or if there were existing issues. For the requests that work, I see some retransmissions occurring, so there may be some timing issues, even though the PLM responded. Here are the logs, following by a wireshark hex dump of the payloads. These first two commands work but with (unnecessary?) retransmissions. 18/01/2014 14:41:55 Running: l garage status 18/01/2014 14:41:57 [Insteon::BaseMessage] WARN: now resending obj=$l_garage; command=status_request after 1 attempts. 18/01/2014 14:41:57 [Insteon::BaseObject] received status for $l_garage with on-level: 0%, hops left: 2 18/01/2014 14:41:57 [Insteon::BaseObject] $l_garage::set_receive(off, $PLM) 00000000 02 62 28 7a f2 0a 19 00 .b(z.... 00000000 02 62 28 7a f2 0a 19 00 06 .b(z.... . 00000008 02 62 28 7a f2 0a 19 00 .b(z.... 00000009 15 . 0000000A 02 50 28 7a f2 20 d9 56 2b 00 00 .P(z. .V +.. 18/01/2014 14:47:14 Running: l garage get engine version 18/01/2014 14:47:16 [Insteon::BaseMessage] WARN: now resending obj=$l_garage; command=get_engine_version after 1 attempts. 18/01/2014 14:47:16 [Insteon::BaseObject] received engine version for $l_garage of I2CS. hops left: 2 00000010 02 62 28 7a f2 0a 0d 00 .b(z.... 00000015 02 62 28 7a f2 0a 0d 00 06 .b(z.... . 00000018 02 62 28 7a f2 0a 0d 00 .b(z.... 0000001E 15 . 0000001F 02 50 28 7a f2 20 d9 56 2b 0d 02 .P(z. .V +.. Here is where it goes wrong. It appears that Insteon_PLM TCP version somehow fails to receive / decode the response to the scan link table. I guess I need to dig down into the code and callback routines to figure out why this is failing. I'm not sure where to begin to look. 18/01/2014 14:48:42 Running: l garage scan link table 18/01/2014 14:48:42 [Insteon::ALDB_i2] $l_garage reading ALDB at location: 0x0000 18/01/2014 14:48:44 [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:read_write_aldb; type:direct; group: 18/01/2014 14:48:44 [Insteon::ALDB_i2] $l_garage reading ALDB at location: 0x0ff7 18/01/2014 14:48:47 [Insteon::BaseMessage] WARN: now resending obj=$l_garage; command=read_write_aldb; extra=0000000ff701000000000000000000 after 1 attempts. 18/01/2014 14:48:50 [Insteon::BaseMessage] WARN: now resending obj=$l_garage; command=read_write_aldb; extra=0000000ff701000000000000000000 after 2 attempts. 18/01/2014 14:48:53 [Insteon::BaseMessage] WARN: now resending obj=$l_garage; command=read_write_aldb; extra=0000000ff701000000000000000000 after 3 attempts. 18/01/2014 14:48:56 [Insteon::BaseMessage] WARN: now resending obj=$l_garage; command=read_write_aldb; extra=0000000ff701000000000000000000 after 4 attempts. 18/01/2014 14:48:57 [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:read_write_aldb; type:direct; group: 18/01/2014 14:48:57 [Insteon::ALDB_i2] $l_garage reading ALDB at location: 0x0fef 18/01/2014 14:49:01 [Insteon::BaseMessage] WARN: now resending obj=$l_garage; command=read_write_aldb; extra=0000000fef01000000000000000000 after 1 attempts. 18/01/2014 14:49:02 [Insteon::BaseMessage] WARN: now resending obj=$l_garage; command=read_write_aldb; extra=0000000fef01000000000000000000 after 2 attempts. 18/01/2014 14:49:02 [Insteon::BaseMessage] Hop count not increased for $l_garage because no_hop_increase flag was set. 18/01/2014 14:49:05 [Insteon::BaseMessage] WARN: now resending obj=$l_garage; command=read_write_aldb; extra=0000000fef01000000000000000000 after 3 attempts. 18/01/2014 14:49:08 [Insteon::BaseMessage] WARN: now resending obj=$l_garage; command=read_write_aldb; extra=0000000fef01000000000000000000 after 4 attempts. 18/01/2014 14:49:09 [Insteon::BaseInterface] WARN: number of retries (5) for obj=$l_garage; command=read_write_aldb; extra=0000000fef01000000000000000000 exceeds limit. Now moving on... 00000020 02 62 28 7a f2 1a 2f 00 00 00 00 00 01 00 00 00 .b(z../. ........ 00000030 00 00 00 00 00 d0 ...... 0000002A 02 62 28 7a f2 1a 2f 00 00 00 00 00 01 00 00 00 .b(z../. ........ 0000003A 00 00 00 00 00 d0 06 ....... 00000041 02 50 28 7a f2 20 d9 56 26 2f 00 .P(z. .V &/. 0000004C 02 51 28 7a f2 20 d9 56 12 2f 00 00 01 0f ff 00 .Q(z. .V ./...... 0000005C a2 00 20 d9 56 ff 1f 01 b2 .. .V... . 00000036 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. ........ 00000046 00 00 00 00 00 ca ...... 00000065 02 . 00000066 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 b(z../.. ....... 00000075 00 00 00 00 00 ca 06 ....... 0000004C 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. ........ 0000005C 00 00 00 00 00 ca ...... 0000007C 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. ........ 0000008C 00 00 00 00 00 ca 06 ....... 00000093 02 50 28 7a f2 20 d9 56 2b 2f 00 .P(z. .V +/. 00000062 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. ........ 00000072 00 00 00 00 00 ca ...... 0000009E 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. ........ 000000AE 00 00 00 00 00 ca 06 ....... 00000078 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. ........ 00000088 00 00 00 00 00 ca ...... 000000B5 02 62 28 .b( 000000B8 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 00 00 00 z../.... ........ 000000C8 00 00 ca 06 .... 0000008E 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. ........ 0000009E 00 00 00 00 00 ca ...... 000000CC 15 15 .. 000000CE 02 51 28 7a f2 20 d9 56 12 2f 00 00 01 0f f7 00 .Q(z. .V ./...... 000000DE 22 00 20 d9 56 ff 1f 01 3a ". .V... : 000000A4 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. ........ 000000B4 00 00 00 00 00 d2 ...... 000000E7 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. ........ 000000F7 00 00 00 00 00 d2 06 ....... 000000BA 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. ........ 000000CA 00 00 00 00 00 d2 ...... 000000FE 15 15 .. 000000D0 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. ........ 000000E0 00 00 00 00 00 d2 ...... 00000100 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. ........ 00000110 00 00 00 00 00 d2 06 ....... 00000117 02 50 28 7a f2 20 d9 56 26 2f 00 .P(z. .V &/. |
From: Kevin R. K. <ke...@kr...> - 2014-01-20 20:28:40
|
Interesting, George, can you try and run things with debug set to Insteon:4. Using level 4 ought to result in nicely formatted decoded messages in the print log, negating the need for the wireshark log. It is hard to say what is going on, it is possible that the timing just needs to be increased. At the moment, there is nothing in the code that would increase the delay for all messages across the board. There are two ways you can kinda hack a delay in for the time being: 1. In your ini file set Insteon_PLM_xmit_delay to something like 1 second. The default is .25. This will slow MH down so that it can only send an insteon message to the PLM once a second. 2. For each insteon object you can set a timeout factor, so $object->timeout_factor(1.5) would add a 50% increase to the message transmission delay. You would have to do this on every device. Of course if these turn out to be solutions, we can certainly gin up a global setting for you. On Sat, Jan 18, 2014 at 12:15 PM, George Clark <ge...@fe...> wrote: > Hi all, > > I've re-applied the TCP patch against the latest Insteon_PLM code. > Basic functionality works well. I'm able to control devices via > misterhouse and the PLM. This includes both Insteon and X10 devices. > However some device requests fail with retries. I suspect that it's > an issue in the IP changes and receiving information from the device. > > I wonder if the original author ever got these functions working for IP, > or if there were existing issues. For the requests that work, I see > some retransmissions occurring, so there may be some timing issues, > even though the PLM responded. > > Here are the logs, following by a wireshark hex dump of the payloads. > These first two commands work but with (unnecessary?) retransmissions. > > 18/01/2014 14:41:55 Running: l garage status > 18/01/2014 14:41:57 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=status_request after 1 attempts. > 18/01/2014 14:41:57 [Insteon::BaseObject] received status for $l_garage > with on-level: 0%, hops left: 2 > 18/01/2014 14:41:57 [Insteon::BaseObject] $l_garage::set_receive(off, > $PLM) > > 00000000 02 62 28 7a f2 0a 19 00 .b(z.... > 00000000 02 62 28 7a f2 0a 19 00 06 .b(z.... . > 00000008 02 62 28 7a f2 0a 19 00 .b(z.... > 00000009 15 . > 0000000A 02 50 28 7a f2 20 d9 56 2b 00 00 .P(z. .V +.. > > > 18/01/2014 14:47:14 Running: l garage get engine version > 18/01/2014 14:47:16 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=get_engine_version after 1 attempts. > 18/01/2014 14:47:16 [Insteon::BaseObject] received engine version for > $l_garage of I2CS. hops left: 2 > > > 00000010 02 62 28 7a f2 0a 0d 00 .b(z.... > 00000015 02 62 28 7a f2 0a 0d 00 06 .b(z.... . > 00000018 02 62 28 7a f2 0a 0d 00 .b(z.... > 0000001E 15 . > 0000001F 02 50 28 7a f2 20 d9 56 2b 0d 02 .P(z. .V +.. > > > Here is where it goes wrong. It appears that Insteon_PLM TCP version > somehow fails to receive / decode the response to the scan link table. > I guess I need to dig down into the code and callback routines to figure > out why this is failing. I'm not sure where to begin to look. > > 18/01/2014 14:48:42 Running: l garage scan link table > 18/01/2014 14:48:42 [Insteon::ALDB_i2] $l_garage reading ALDB at > location: 0x0000 > 18/01/2014 14:48:44 [Insteon::BaseInterface] DEBUG: PLM > command:insteon_ext_received; Device command:read_write_aldb; > type:direct; group: > 18/01/2014 14:48:44 [Insteon::ALDB_i2] $l_garage reading ALDB at > location: 0x0ff7 > 18/01/2014 14:48:47 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000ff701000000000000000000 after 1 attempts. > 18/01/2014 14:48:50 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000ff701000000000000000000 after 2 attempts. > 18/01/2014 14:48:53 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000ff701000000000000000000 after 3 attempts. > 18/01/2014 14:48:56 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000ff701000000000000000000 after 4 attempts. > 18/01/2014 14:48:57 [Insteon::BaseInterface] DEBUG: PLM > command:insteon_ext_received; Device command:read_write_aldb; > type:direct; group: > 18/01/2014 14:48:57 [Insteon::ALDB_i2] $l_garage reading ALDB at > location: 0x0fef > 18/01/2014 14:49:01 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000fef01000000000000000000 after 1 attempts. > 18/01/2014 14:49:02 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000fef01000000000000000000 after 2 attempts. > 18/01/2014 14:49:02 [Insteon::BaseMessage] Hop count not increased for > $l_garage because no_hop_increase flag was set. > 18/01/2014 14:49:05 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000fef01000000000000000000 after 3 attempts. > 18/01/2014 14:49:08 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000fef01000000000000000000 after 4 attempts. > 18/01/2014 14:49:09 [Insteon::BaseInterface] WARN: number of retries > (5) for obj=$l_garage; command=read_write_aldb; > extra=0000000fef01000000000000000000 exceeds limit. Now moving on... > > > > 00000020 02 62 28 7a f2 1a 2f 00 00 00 00 00 01 00 00 00 .b(z../. > ........ > 00000030 00 00 00 00 00 d0 ...... > 0000002A 02 62 28 7a f2 1a 2f 00 00 00 00 00 01 00 00 00 .b(z../. > ........ > 0000003A 00 00 00 00 00 d0 06 ....... > 00000041 02 50 28 7a f2 20 d9 56 26 2f 00 .P(z. .V &/. > 0000004C 02 51 28 7a f2 20 d9 56 12 2f 00 00 01 0f ff 00 .Q(z. .V > ./...... > 0000005C a2 00 20 d9 56 ff 1f 01 b2 .. .V... . > 00000036 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. > ........ > 00000046 00 00 00 00 00 ca ...... > 00000065 02 . > 00000066 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 b(z../.. > ....... > 00000075 00 00 00 00 00 ca 06 ....... > 0000004C 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. > ........ > 0000005C 00 00 00 00 00 ca ...... > 0000007C 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. > ........ > 0000008C 00 00 00 00 00 ca 06 ....... > 00000093 02 50 28 7a f2 20 d9 56 2b 2f 00 .P(z. .V +/. > 00000062 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. > ........ > 00000072 00 00 00 00 00 ca ...... > 0000009E 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. > ........ > 000000AE 00 00 00 00 00 ca 06 ....... > 00000078 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. > ........ > 00000088 00 00 00 00 00 ca ...... > 000000B5 02 62 28 .b( > 000000B8 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 00 00 00 z../.... > ........ > 000000C8 00 00 ca 06 .... > 0000008E 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. > ........ > 0000009E 00 00 00 00 00 ca ...... > 000000CC 15 15 .. > 000000CE 02 51 28 7a f2 20 d9 56 12 2f 00 00 01 0f f7 00 .Q(z. .V > ./...... > 000000DE 22 00 20 d9 56 ff 1f 01 3a ". .V... : > 000000A4 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. > ........ > 000000B4 00 00 00 00 00 d2 ...... > 000000E7 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. > ........ > 000000F7 00 00 00 00 00 d2 06 ....... > 000000BA 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. > ........ > 000000CA 00 00 00 00 00 d2 ...... > 000000FE 15 15 .. > 000000D0 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. > ........ > 000000E0 00 00 00 00 00 d2 ...... > 00000100 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. > ........ > 00000110 00 00 00 00 00 d2 06 ....... > 00000117 02 50 28 7a f2 20 d9 56 26 2f 00 .P(z. .V &/. > > > > > ------------------------------------------------------------------------------ > CenturyLink Cloud: The Leader in Enterprise Cloud Services. > Learn Why More Businesses Are Choosing CenturyLink Cloud For > Critical Workloads, Development Environments & Everything In Between. > Get a Quote or Start a Free Trial Today. > > http://pubads.g.doubleclick.net/gampad/clk?id=119420431&iu=/4140/ostg.clktrk > ________________________________________________________ > To unsubscribe from this list, go to: > http://sourceforge.net/mail/?group_id=1365 > > |
From: George C. <ge...@fe...> - 2014-01-21 00:14:47
|
Hi Kevin, I've restarted mh with debug set to Insteon:4. Excellent debug messages. Thanks for the suggestion. I ran and captured some individual device link scan tests, with the Insteon_PLM_xmit_delay unset, and set to 1. This time around, the individual scans appeared to work, but I left the Insteon_PLM_xmit_delay = 1 anyway for safety and ran a "scan all links" command. That completed with only two devices exhibiting the retransmit / "moving on" failure. One of them scanned fine when run manually, but the l_front_porch remains unsuccessful. - The circuit is on a different phase from the PLM, but there are 4 devices on the circuit, and 3 scanned just fine. Also I believe everything in my network is dual mode, so I don't think it's a powerline issue. I have an old X10 phase bridge still installed, I'm not sure if that will help the insteon signal. - Controls; on, off, set level, get status, get engine ... all work fine. Seems to be only scan link that fails. Hm... This seems like an IOLink that was "stuck" the other day, not responding to the get status command. I just factory reset the switch, re-linked it to the PLM, and success! It looks like there were a few resends still. One due to a missing ACK, I'm not sure why the others occurred. But it's working. Based on this, it looks like the IP code from https://github.com/AndTH/misterhouse/tree/InsteonIP works, as long as it's merged into the link3 changes in the hollie master branch. I'll see if I can clean it up so it can be merged back into hollie, maybe with some refactoring. Anyway, here are the linking results after the factory reset. 20/01/2014 17:42:51 Running: l front porch scan link table 20/01/2014 17:42:51 [Insteon::ALDB_i2] $l_front_porch reading ALDB at location: 0x0000 20/01/2014 17:42:51 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=read_write_aldb; extra=000000000001000000000000000000 incurred delay of 0.00 seconds; starting hop-count: 2 20/01/2014 17:42:51 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=read_write_aldb; extra=000000000001000000000000000000 incurred delay of 0.00 seconds; starting hop-count: 2 20/01/2014 17:42:51 [Insteon_PLM] DEBUG3: Sending PLM raw data: 026228f55c1a2f0000000000010000000000000000d0 20/01/2014 17:42:51 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 1a Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 2 Max Hops: 2 Insteon Message: 2f0000000000010000000000000000d0 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00000000010000000000000000d0 20/01/2014 17:42:51 [Insteon PLM] data recieved b(?\?/? 20/01/2014 17:42:51 [Insteon_PLM] DEBUG3: Received PLM raw data: 026228f55c1a2f0000000000010000000000000000d006 20/01/2014 17:42:51 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 1a Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 2 Max Hops: 2 Insteon Message: 2f0000000000010000000000000000d0 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00000000010000000000000000d006 PLM Response: (06) ACK 20/01/2014 17:42:51 [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$l_front_porch; command=read_write_aldb; extra=000000000001000000000000000000 20/01/2014 17:42:51 [Insteon PLM] data recieved P(?\ ?V"/ 20/01/2014 17:42:51 [Insteon_PLM] DEBUG3: Received PLM raw data: 025028f55c20d956222f00 20/01/2014 17:42:51 [Insteon_PLM] DEBUG4: PLM Command: (0250) insteon_received From Address: 28:f5:5c To Address: 20:d9:56 Message Flags: 22 Message Type: (001) ACK of Direct Message Message Length: (0) Standard Length Hops Left: 0 Max Hops: 2 Insteon Message: 2f00 Cmd 1: (2f) Light OFF at Ramp Rate Cmd 2: (00) Ramp Rate 20/01/2014 17:42:51 [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:read_write_aldb; type:direct; group: 20/01/2014 17:42:51 [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $l_front_porch 20/01/2014 17:42:51 [Insteon::BaseObject] DEBUG4: $l_front_porch->default_hop_count()=2 :: hop_array[]=2123133322 20/01/2014 17:42:51 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0000] received: 00 for _mem_activity=scan _mem_action=aldb_i2read 20/01/2014 17:42:51 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0000] received ack 20/01/2014 17:42:52 [Insteon PLM] data recieved Q(?\ ?V/?? ?Vh 20/01/2014 17:42:52 [Insteon_PLM] DEBUG3: Received PLM raw data: 025128f55c20d956112f0000010fff00ea0120d956031c0168 20/01/2014 17:42:52 [Insteon_PLM] DEBUG4: PLM Command: (0251) insteon_ext_received From Address: 28:f5:5c To Address: 20:d9:56 Message Flags: 11 Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 0 Max Hops: 1 Insteon Message: 2f0000010fff00ea0120d956031c0168 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00010fff00ea0120d956031c0168 20/01/2014 17:42:52 [Insteon::BaseInterface] DEBUG3: Message received with 0 hops left, plus ACK will take 1 to deliver, delaying next transmit by 250 milliseconds to avoid collisions. 20/01/2014 17:42:52 [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:read_write_aldb; type:direct; group: 20/01/2014 17:42:52 [Insteon::BaseInterface] Processing message for $l_front_porch 20/01/2014 17:42:52 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $l_front_porch 20/01/2014 17:42:52 [Insteon::BaseObject] DEBUG4: $l_front_porch->default_hop_count()=2 :: hop_array[]=1212313332 20/01/2014 17:42:52 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0000] received: 0000010fff00ea0120d956031c0168 for _mem_activity=scan _mem_action=aldb_i2readack 20/01/2014 17:42:52 [Insteon::ALDB_i2] DEBUG4: Start of scan; initializing aldb structure 20/01/2014 17:42:52 [Insteon::ALDB_i2] DEBUG4: active link found; adding address [0fff] to aldb 20/01/2014 17:42:52 [Insteon::ALDB_i2] $l_front_porch reading ALDB at location: 0x0ff7 20/01/2014 17:42:52 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=read_write_aldb; extra=0000000ff701000000000000000000 incurred delay of 0.26 seconds; starting hop-count: 2 20/01/2014 17:42:52 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=read_write_aldb; extra=0000000ff701000000000000000000 incurred delay of 0.26 seconds; starting hop-count: 2 20/01/2014 17:42:52 [Insteon_PLM] DEBUG3: Sending PLM raw data: 026228f55c1a2f0000000ff7010000000000000000ca 20/01/2014 17:42:52 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 1a Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 2 Max Hops: 2 Insteon Message: 2f0000000ff7010000000000000000ca Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00000ff7010000000000000000ca 20/01/2014 17:42:52 [Insteon PLM] data recieved b(?\?/?? 20/01/2014 17:42:52 [Insteon_PLM] DEBUG3: Received PLM raw data: 026228f55c1a2f0000000ff7010000000000000000ca06 20/01/2014 17:42:52 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 1a Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 2 Max Hops: 2 Insteon Message: 2f0000000ff7010000000000000000ca Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00000ff7010000000000000000ca06 PLM Response: (06) ACK 20/01/2014 17:42:52 [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$l_front_porch; command=read_write_aldb; extra=0000000ff701000000000000000000 20/01/2014 17:42:52 [Insteon PLM] data recieved P(?\ ?V&/ 20/01/2014 17:42:52 [Insteon_PLM] DEBUG3: Received PLM raw data: 025028f55c20d956262f00 20/01/2014 17:42:52 [Insteon_PLM] DEBUG4: PLM Command: (0250) insteon_received From Address: 28:f5:5c To Address: 20:d9:56 Message Flags: 26 Message Type: (001) ACK of Direct Message Message Length: (0) Standard Length Hops Left: 1 Max Hops: 2 Insteon Message: 2f00 Cmd 1: (2f) Light OFF at Ramp Rate Cmd 2: (00) Ramp Rate 20/01/2014 17:42:52 [Insteon::BaseInterface] DEBUG3: Message received with 1 hops left, delaying next transmit by 150 milliseconds to avoid collisions. 20/01/2014 17:42:52 [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:read_write_aldb; type:direct; group: 20/01/2014 17:42:52 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $l_front_porch 20/01/2014 17:42:52 [Insteon::BaseObject] DEBUG4: $l_front_porch->default_hop_count()=2 :: hop_array[]=1121231333 20/01/2014 17:42:52 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0ff7] received: 00 for _mem_activity=scan _mem_action=aldb_i2read 20/01/2014 17:42:52 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0ff7] received ack 20/01/2014 17:42:53 [Insteon PLM] data recieved Q(?\ ?V/?? ?V?? 20/01/2014 17:42:53 [Insteon_PLM] DEBUG3: Received PLM raw data: 025128f55c20d956112f0000010ff700aa0020d956ff1c01b5 20/01/2014 17:42:53 [Insteon_PLM] DEBUG4: PLM Command: (0251) insteon_ext_received From Address: 28:f5:5c To Address: 20:d9:56 Message Flags: 11 Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 0 Max Hops: 1 Insteon Message: 2f0000010ff700aa0020d956ff1c01b5 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00010ff700aa0020d956ff1c01b5 20/01/2014 17:42:53 [Insteon::BaseInterface] DEBUG3: Message received with 0 hops left, plus ACK will take 1 to deliver, delaying next transmit by 250 milliseconds to avoid collisions. 20/01/2014 17:42:53 [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:read_write_aldb; type:direct; group: 20/01/2014 17:42:53 [Insteon::BaseInterface] Processing message for $l_front_porch 20/01/2014 17:42:53 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $l_front_porch 20/01/2014 17:42:53 [Insteon::BaseObject] DEBUG4: $l_front_porch->default_hop_count()=2 :: hop_array[]=1112123133 20/01/2014 17:42:53 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0ff7] received: 0000010ff700aa0020d956ff1c01b5 for _mem_activity=scan _mem_action=aldb_i2readack 20/01/2014 17:42:53 [Insteon::ALDB_i2] DEBUG4: active link found; adding address [0ff7] to aldb 20/01/2014 17:42:53 [Insteon::ALDB_i2] $l_front_porch reading ALDB at location: 0x0fef 20/01/2014 17:42:53 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=read_write_aldb; extra=0000000fef01000000000000000000 incurred delay of 0.26 seconds; starting hop-count: 2 20/01/2014 17:42:53 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=read_write_aldb; extra=0000000fef01000000000000000000 incurred delay of 0.26 seconds; starting hop-count: 2 20/01/2014 17:42:53 [Insteon_PLM] DEBUG3: Sending PLM raw data: 026228f55c1a2f0000000fef010000000000000000d2 20/01/2014 17:42:53 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 1a Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 2 Max Hops: 2 Insteon Message: 2f0000000fef010000000000000000d2 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00000fef010000000000000000d2 20/01/2014 17:42:53 [Insteon PLM] data recieved b(?\?/?? 20/01/2014 17:42:53 [Insteon_PLM] DEBUG3: Received PLM raw data: 026228f55c1a2f0000000fef010000000000000000d206 20/01/2014 17:42:53 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 1a Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 2 Max Hops: 2 Insteon Message: 2f0000000fef010000000000000000d2 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00000fef010000000000000000d206 PLM Response: (06) ACK 20/01/2014 17:42:53 [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$l_front_porch; command=read_write_aldb; extra=0000000fef01000000000000000000 20/01/2014 17:42:55 [Insteon PLM] data recieved Q(?\ ?V/?? 20/01/2014 17:42:55 [Insteon_PLM] DEBUG3: Received PLM raw data: 025128f55c20d956172f0000010fef000000000000000000d2 20/01/2014 17:42:55 [Insteon_PLM] DEBUG4: PLM Command: (0251) insteon_ext_received From Address: 28:f5:5c To Address: 20:d9:56 Message Flags: 17 Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 1 Max Hops: 3 Insteon Message: 2f0000010fef000000000000000000d2 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00010fef000000000000000000d2 20/01/2014 17:42:55 [Insteon::BaseInterface] DEBUG3: Message received with 1 hops left, plus ACK will take 3 to deliver, delaying next transmit by 850 milliseconds to avoid collisions. 20/01/2014 17:42:55 [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:read_write_aldb; type:direct; group: 20/01/2014 17:42:55 [Insteon::BaseInterface] Processing message for $l_front_porch 20/01/2014 17:42:55 [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $l_front_porch 20/01/2014 17:42:55 [Insteon::BaseObject] DEBUG4: $l_front_porch->default_hop_count()=2 :: hop_array[]=2111212313 20/01/2014 17:42:55 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0fef] received: 0000010fef000000000000000000d2 for _mem_activity=scan _mem_action=aldb_i2read 20/01/2014 17:42:55 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0fef] ack not received. ignoring message 20/01/2014 17:42:56 [Insteon::BaseMessage] WARN: now resending obj=$l_front_porch; command=read_write_aldb; extra=0000000fef01000000000000000000 after 1 attempts. 20/01/2014 17:42:56 [Insteon::BaseObject] DEBUG3: Adding hop count of 3 to hop_array of $l_front_porch 20/01/2014 17:42:56 [Insteon::BaseObject] DEBUG4: $l_front_porch->default_hop_count()=2 :: hop_array[]=3211121231 20/01/2014 17:42:56 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=read_write_aldb; extra=0000000fef01000000000000000000 incurred delay of 3.26 seconds; starting hop-count: 2 20/01/2014 17:42:56 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=read_write_aldb; extra=0000000fef01000000000000000000 incurred delay of 3.26 seconds; starting hop-count: 2 20/01/2014 17:42:56 [Insteon_PLM] DEBUG3: Sending PLM raw data: 026228f55c1a2f0000000fef010000000000000000d2 20/01/2014 17:42:56 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 1a Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 2 Max Hops: 2 Insteon Message: 2f0000000fef010000000000000000d2 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00000fef010000000000000000d2 20/01/2014 17:42:56 [Insteon PLM] data recieved b(?\?/?? 20/01/2014 17:42:56 [Insteon_PLM] DEBUG3: Received PLM raw data: 026228f55c1a2f0000000fef010000000000000000d206 20/01/2014 17:42:56 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 1a Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 2 Max Hops: 2 Insteon Message: 2f0000000fef010000000000000000d2 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00000fef010000000000000000d206 PLM Response: (06) ACK 20/01/2014 17:42:56 [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$l_front_porch; command=read_write_aldb; extra=0000000fef01000000000000000000 20/01/2014 17:42:59 [Insteon::BaseMessage] WARN: now resending obj=$l_front_porch; command=read_write_aldb; extra=0000000fef01000000000000000000 after 2 attempts. 20/01/2014 17:42:59 [Insteon::BaseObject] DEBUG3: Adding hop count of 3 to hop_array of $l_front_porch 20/01/2014 17:42:59 [Insteon::BaseObject] DEBUG4: $l_front_porch->default_hop_count()=2 :: hop_array[]=3321112123 20/01/2014 17:42:59 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=read_write_aldb; extra=0000000fef01000000000000000000 incurred delay of 6.27 seconds; starting hop-count: 2 20/01/2014 17:42:59 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=read_write_aldb; extra=0000000fef01000000000000000000 incurred delay of 6.27 seconds; starting hop-count: 2 20/01/2014 17:42:59 [Insteon_PLM] DEBUG3: Sending PLM raw data: 026228f55c1a2f0000000fef010000000000000000d2 20/01/2014 17:42:59 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 1a Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 2 Max Hops: 2 Insteon Message: 2f0000000fef010000000000000000d2 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00000fef010000000000000000d2 20/01/2014 17:42:59 [Insteon PLM] data recieved b(?\?/?? 20/01/2014 17:42:59 [Insteon_PLM] DEBUG3: Received PLM raw data: 026228f55c1a2f0000000fef010000000000000000d206 20/01/2014 17:42:59 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 1a Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 2 Max Hops: 2 Insteon Message: 2f0000000fef010000000000000000d2 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00000fef010000000000000000d206 PLM Response: (06) ACK 20/01/2014 17:42:59 [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$l_front_porch; command=read_write_aldb; extra=0000000fef01000000000000000000 20/01/2014 17:42:59 [Insteon PLM] data recieved P(?\ ?V"/ 20/01/2014 17:42:59 [Insteon_PLM] DEBUG3: Received PLM raw data: 025028f55c20d956222f00 20/01/2014 17:42:59 [Insteon_PLM] DEBUG4: PLM Command: (0250) insteon_received From Address: 28:f5:5c To Address: 20:d9:56 Message Flags: 22 Message Type: (001) ACK of Direct Message Message Length: (0) Standard Length Hops Left: 0 Max Hops: 2 Insteon Message: 2f00 Cmd 1: (2f) Light OFF at Ramp Rate Cmd 2: (00) Ramp Rate 20/01/2014 17:42:59 [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:read_write_aldb; type:direct; group: 20/01/2014 17:42:59 [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $l_front_porch 20/01/2014 17:42:59 [Insteon::BaseObject] DEBUG4: $l_front_porch->default_hop_count()=2 :: hop_array[]=2332111212 20/01/2014 17:42:59 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0fef] received: 00 for _mem_activity=scan _mem_action=aldb_i2read 20/01/2014 17:42:59 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0fef] received ack 20/01/2014 17:43:00 [Insteon PLM] data recieved Q(?\ ?V/?? 20/01/2014 17:43:00 [Insteon_PLM] DEBUG3: Received PLM raw data: 025128f55c20d956112f0000010fef000000000000000000d2 20/01/2014 17:43:00 [Insteon_PLM] DEBUG4: PLM Command: (0251) insteon_ext_received From Address: 28:f5:5c To Address: 20:d9:56 Message Flags: 11 Message Type: (000) Direct Message Message Length: (1) Extended Length Hops Left: 0 Max Hops: 1 Insteon Message: 2f0000010fef000000000000000000d2 Cmd 1: (2f) Read/Write ALL-Link Database Cmd 2: (00) Command in D2 D1-D14: 00010fef000000000000000000d2 20/01/2014 17:43:00 [Insteon::BaseInterface] DEBUG3: Message received with 0 hops left, plus ACK will take 1 to deliver, delaying next transmit by 250 milliseconds to avoid collisions. 20/01/2014 17:43:00 [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:read_write_aldb; type:direct; group: 20/01/2014 17:43:00 [Insteon::BaseInterface] Processing message for $l_front_porch 20/01/2014 17:43:00 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $l_front_porch 20/01/2014 17:43:00 [Insteon::BaseObject] DEBUG4: $l_front_porch->default_hop_count()=2 :: hop_array[]=1233211121 20/01/2014 17:43:00 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0fef] received: 0000010fef000000000000000000d2 for _mem_activity=scan _mem_action=aldb_i2readack 20/01/2014 17:43:00 [Insteon::ALDB_i2] DEBUG4: scan done; adding last address [0fef] to empty array 20/01/2014 17:43:00 [Insteon::ALDB_i2] $l_front_porch completed link memory scan: status: good 20/01/2014 17:43:00 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=status_request incurred delay of 0.26 seconds; starting hop-count: 2 20/01/2014 17:43:00 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=status_request incurred delay of 0.26 seconds; starting hop-count: 2 20/01/2014 17:43:00 [Insteon_PLM] DEBUG3: Sending PLM raw data: 026228f55c0a1900 20/01/2014 17:43:00 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 0a Message Type: (000) Direct Message Message Length: (0) Standard Length Hops Left: 2 Max Hops: 2 Insteon Message: 1900 Cmd 1: (19) Light Status Request Cmd 2: (00) On Level 20/01/2014 17:43:00 [Insteon PLM] data recieved b(?\ 20/01/2014 17:43:00 [Insteon_PLM] DEBUG3: Received PLM raw data: 026228f55c0a190006 20/01/2014 17:43:00 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 0a Message Type: (000) Direct Message Message Length: (0) Standard Length Hops Left: 2 Max Hops: 2 Insteon Message: 1900 Cmd 1: (19) Light Status Request Cmd 2: (00) On Level PLM Response: (06) ACK 20/01/2014 17:43:00 [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$l_front_porch; command=status_request 20/01/2014 17:43:02 [Insteon::BaseMessage] WARN: now resending obj=$l_front_porch; command=status_request after 1 attempts. 20/01/2014 17:43:02 [Insteon::BaseObject] DEBUG3: Adding hop count of 3 to hop_array of $l_front_porch 20/01/2014 17:43:02 [Insteon::BaseObject] DEBUG4: $l_front_porch->default_hop_count()=2 :: hop_array[]=3123321112 20/01/2014 17:43:02 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=status_request incurred delay of 2.17 seconds; starting hop-count: 2 20/01/2014 17:43:02 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; command=status_request incurred delay of 2.17 seconds; starting hop-count: 2 20/01/2014 17:43:02 [Insteon_PLM] DEBUG3: Sending PLM raw data: 026228f55c0a1900 20/01/2014 17:43:02 [Insteon_PLM] DEBUG4: PLM Command: (0262) insteon_send To Address: 28:f5:5c Message Flags: 0a Message Type: (000) Direct Message Message Length: (0) Standard Length Hops Left: 2 Max Hops: 2 Insteon Message: 1900 Cmd 1: (19) Light Status Request Cmd 2: (00) On Level 20/01/2014 17:43:02 [Insteon PLM] data recieved 20/01/2014 17:43:02 [Insteon_PLM] DEBUG3: Received PLM raw data: 1515 20/01/2014 17:43:02 [Insteon_PLM] DEBUG3: Interface extremely busy. Resending command after delaying for 1 second 20/01/2014 17:43:02 [Insteon PLM] data recieved P(?\ ?V+? 20/01/2014 17:43:02 [Insteon_PLM] DEBUG3: Received PLM raw data: 025028f55c20d9562b03ff 20/01/2014 17:43:02 [Insteon_PLM] DEBUG4: PLM Command: (0250) insteon_received From Address: 28:f5:5c To Address: 20:d9:56 Message Flags: 2b Message Type: (001) ACK of Direct Message Message Length: (0) Standard Length Hops Left: 2 Max Hops: 3 Insteon Message: 03ff Cmd 1: (03) Device Request Cmd 2: (ff) 20/01/2014 17:43:02 [Insteon::BaseInterface] DEBUG3: Message received with 2 hops left, delaying next transmit by 250 milliseconds to avoid collisions. 20/01/2014 17:43:02 [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:; type:direct; group: 20/01/2014 17:43:02 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $l_front_porch 20/01/2014 17:43:02 [Insteon::BaseObject] DEBUG4: $l_front_porch->default_hop_count()=2 :: hop_array[]=1312332111 20/01/2014 17:43:02 [Insteon::BaseObject] received status for $l_front_porch with on-level: 100%, hops left: 2 20/01/2014 17:43:02 [Insteon::BaseObject] $l_front_porch::set_receive(100%, $PLM) 20/01/2014 17:43:02 [Insteon::BaseObject] The Link Table Version for $l_front_porch has been updated to version number 03 20/01/2014 17:43:02 [Insteon::AllLinkDatabase] Link table for $l_front_porch health: good On 01/20/2014 03:28 PM, Kevin Robert Keegan wrote: > Interesting, > > George, can you try and run things with debug set to Insteon:4. Using > level 4 ought to result in nicely formatted decoded messages in the > print log, negating the need for the wireshark log. > > It is hard to say what is going on, it is possible that the timing > just needs to be increased. At the moment, there is nothing in the > code that would increase the delay for all messages across the board. > There are two ways you can kinda hack a delay in for the time being: > > 1. In your ini file set Insteon_PLM_xmit_delay to something like 1 > second. The default is .25. This will slow MH down so that it can > only send an insteon message to the PLM once a second. > > 2. For each insteon object you can set a timeout factor, so > $object->timeout_factor(1.5) would add a 50% increase to the message > transmission delay. You would have to do this on every device. > > Of course if these turn out to be solutions, we can certainly gin up a > global setting for you. > > > On Sat, Jan 18, 2014 at 12:15 PM, George Clark <ge...@fe... > <mailto:ge...@fe...>> wrote: > > Hi all, > > I've re-applied the TCP patch against the latest Insteon_PLM code. > Basic functionality works well. I'm able to control devices via > misterhouse and the PLM. This includes both Insteon and X10 devices. > However some device requests fail with retries. I suspect that it's > an issue in the IP changes and receiving information from the device. > > I wonder if the original author ever got these functions working > for IP, > or if there were existing issues. For the requests that work, I see > some retransmissions occurring, so there may be some timing issues, > even though the PLM responded. > > Here are the logs, following by a wireshark hex dump of the payloads. > These first two commands work but with (unnecessary?) retransmissions. > > 18/01/2014 14:41:55 Running: l garage status > 18/01/2014 14:41:57 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=status_request after 1 attempts. > 18/01/2014 14:41:57 [Insteon::BaseObject] received status for > $l_garage > with on-level: 0%, hops left: 2 > 18/01/2014 14:41:57 [Insteon::BaseObject] > $l_garage::set_receive(off, $PLM) > > 00000000 02 62 28 7a f2 0a 19 00 .b(z.... > 00000000 02 62 28 7a f2 0a 19 00 06 > .b(z.... . > 00000008 02 62 28 7a f2 0a 19 00 .b(z.... > 00000009 15 . > 0000000A 02 50 28 7a f2 20 d9 56 2b 00 00 > .P(z. .V +.. > > > 18/01/2014 14:47:14 Running: l garage get engine version > 18/01/2014 14:47:16 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=get_engine_version after 1 attempts. > 18/01/2014 14:47:16 [Insteon::BaseObject] received engine version for > $l_garage of I2CS. hops left: 2 > > > 00000010 02 62 28 7a f2 0a 0d 00 .b(z.... > 00000015 02 62 28 7a f2 0a 0d 00 06 > .b(z.... . > 00000018 02 62 28 7a f2 0a 0d 00 .b(z.... > 0000001E 15 . > 0000001F 02 50 28 7a f2 20 d9 56 2b 0d 02 > .P(z. .V +.. > > > Here is where it goes wrong. It appears that Insteon_PLM TCP version > somehow fails to receive / decode the response to the scan link table. > I guess I need to dig down into the code and callback routines to > figure > out why this is failing. I'm not sure where to begin to look. > > 18/01/2014 14:48:42 Running: l garage scan link table > 18/01/2014 14:48:42 [Insteon::ALDB_i2] $l_garage reading ALDB at > location: 0x0000 > 18/01/2014 14:48:44 [Insteon::BaseInterface] DEBUG: PLM > command:insteon_ext_received; Device command:read_write_aldb; > type:direct; group: > 18/01/2014 14:48:44 [Insteon::ALDB_i2] $l_garage reading ALDB at > location: 0x0ff7 > 18/01/2014 14:48:47 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000ff701000000000000000000 after 1 attempts. > 18/01/2014 14:48:50 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000ff701000000000000000000 after 2 attempts. > 18/01/2014 14:48:53 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000ff701000000000000000000 after 3 attempts. > 18/01/2014 14:48:56 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000ff701000000000000000000 after 4 attempts. > 18/01/2014 14:48:57 [Insteon::BaseInterface] DEBUG: PLM > command:insteon_ext_received; Device command:read_write_aldb; > type:direct; group: > 18/01/2014 14:48:57 [Insteon::ALDB_i2] $l_garage reading ALDB at > location: 0x0fef > 18/01/2014 14:49:01 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000fef01000000000000000000 after 1 attempts. > 18/01/2014 14:49:02 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000fef01000000000000000000 after 2 attempts. > 18/01/2014 14:49:02 [Insteon::BaseMessage] Hop count not > increased for > $l_garage because no_hop_increase flag was set. > 18/01/2014 14:49:05 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000fef01000000000000000000 after 3 attempts. > 18/01/2014 14:49:08 [Insteon::BaseMessage] WARN: now resending > obj=$l_garage; command=read_write_aldb; > extra=0000000fef01000000000000000000 after 4 attempts. > 18/01/2014 14:49:09 [Insteon::BaseInterface] WARN: number of retries > (5) for obj=$l_garage; command=read_write_aldb; > extra=0000000fef01000000000000000000 exceeds limit. Now moving on... > > > > 00000020 02 62 28 7a f2 1a 2f 00 00 00 00 00 01 00 00 00 > .b(z../. ........ > 00000030 00 00 00 00 00 d0 ...... > 0000002A 02 62 28 7a f2 1a 2f 00 00 00 00 00 01 00 00 00 > .b(z../. > ........ > 0000003A 00 00 00 00 00 d0 06 ....... > 00000041 02 50 28 7a f2 20 d9 56 26 2f 00 > .P(z. .V &/. > 0000004C 02 51 28 7a f2 20 d9 56 12 2f 00 00 01 0f ff 00 > .Q(z. .V > ./...... > 0000005C a2 00 20 d9 56 ff 1f 01 b2 .. > .V... . > 00000036 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 > .b(z../. ........ > 00000046 00 00 00 00 00 ca ...... > 00000065 02 . > 00000066 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 > b(z../.. > ....... > 00000075 00 00 00 00 00 ca 06 ....... > 0000004C 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 > .b(z../. ........ > 0000005C 00 00 00 00 00 ca ...... > 0000007C 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 > .b(z../. > ........ > 0000008C 00 00 00 00 00 ca 06 ....... > 00000093 02 50 28 7a f2 20 d9 56 2b 2f 00 > .P(z. .V +/. > 00000062 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 > .b(z../. ........ > 00000072 00 00 00 00 00 ca ...... > 0000009E 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 > .b(z../. > ........ > 000000AE 00 00 00 00 00 ca 06 ....... > 00000078 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 > .b(z../. ........ > 00000088 00 00 00 00 00 ca ...... > 000000B5 02 62 28 .b( > 000000B8 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 00 00 00 > z../.... > ........ > 000000C8 00 00 ca 06 .... > 0000008E 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 > .b(z../. ........ > 0000009E 00 00 00 00 00 ca ...... > 000000CC 15 15 .. > 000000CE 02 51 28 7a f2 20 d9 56 12 2f 00 00 01 0f f7 00 > .Q(z. .V > ./...... > 000000DE 22 00 20 d9 56 ff 1f 01 3a ". > .V... : > 000000A4 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 > .b(z../. ........ > 000000B4 00 00 00 00 00 d2 ...... > 000000E7 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 > .b(z../. > ........ > 000000F7 00 00 00 00 00 d2 06 ....... > 000000BA 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 > .b(z../. ........ > 000000CA 00 00 00 00 00 d2 ...... > 000000FE 15 15 .. > 000000D0 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 > .b(z../. ........ > 000000E0 00 00 00 00 00 d2 ...... > 00000100 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 > .b(z../. > ........ > 00000110 00 00 00 00 00 d2 06 ....... > 00000117 02 50 28 7a f2 20 d9 56 26 2f 00 > .P(z. .V &/. > > > > ------------------------------------------------------------------------------ > CenturyLink Cloud: The Leader in Enterprise Cloud Services. > Learn Why More Businesses Are Choosing CenturyLink Cloud For > Critical Workloads, Development Environments & Everything In Between. > Get a Quote or Start a Free Trial Today. > http://pubads.g.doubleclick.net/gampad/clk?id=119420431&iu=/4140/ostg.clktrk > ________________________________________________________ > To unsubscribe from this list, go to: > http://sourceforge.net/mail/?group_id=1365 > > |
From: Kevin R. K. <ke...@kr...> - 2014-01-21 00:36:55
|
Good to hear. As you noted, some of the failures may simply be normal insteon troubles. Can you test one thing for me? I would like to know what happens when you use the hub to control an object. What does MH do if anything? Does it recognize the change? Does it implode when it receives an acknowledgement to a command that it never sent? I could inject some fake messages, but I figure it would be easier for you to test it out. On Mon, Jan 20, 2014 at 4:14 PM, George Clark <ge...@fe...> wrote: > Hi Kevin, > > I've restarted mh with debug set to Insteon:4. Excellent debug messages. > Thanks for the suggestion. > > I ran and captured some individual device link scan tests, with the > Insteon_PLM_xmit_delay unset, and set to 1. This time around, the > individual scans appeared to work, but I left the Insteon_PLM_xmit_delay = > 1 anyway for safety and ran a "scan all links" command. That completed > with only two devices exhibiting the retransmit / "moving on" failure. One > of them scanned fine when run manually, but the l_front_porch remains > unsuccessful. > > - The circuit is on a different phase from the PLM, but there are 4 > devices on the circuit, and 3 scanned just fine. Also I believe everything > in my network is dual mode, so I don't think it's a powerline issue. I > have an old X10 phase bridge still installed, I'm not sure if that will > help the insteon signal. > > - Controls; on, off, set level, get status, get engine ... all work fine. > Seems to be only scan link that fails. > > Hm... This seems like an IOLink that was "stuck" the other day, not > responding to the get status command. I just factory reset the switch, > re-linked it to the PLM, and success! It looks like there were a few > resends still. One due to a missing ACK, I'm not sure why the others > occurred. But it's working. > > Based on this, it looks like the IP code from > https://github.com/AndTH/misterhouse/tree/InsteonIP works, as long as > it's merged into the link3 changes in the hollie master branch. I'll see > if I can clean it up so it can be merged back into hollie, maybe with some > refactoring. > > Anyway, here are the linking results after the factory reset. > > 20/01/2014 17:42:51 Running: l front porch scan link table > 20/01/2014 17:42:51 [Insteon::ALDB_i2] $l_front_porch reading ALDB at > location: 0x0000 > 20/01/2014 17:42:51 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=read_write_aldb; extra=000000000001000000000000000000 incurred > delay of 0.00 seconds; starting hop-count: 2 > 20/01/2014 17:42:51 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=read_write_aldb; extra=000000000001000000000000000000 incurred > delay of 0.00 seconds; starting hop-count: 2 > 20/01/2014 17:42:51 [Insteon_PLM] DEBUG3: Sending PLM raw data: > 026228f55c1a2f0000000000010000000000000000d0 > 20/01/2014 17:42:51 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 1a > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 2f0000000000010000000000000000d0 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00000000010000000000000000d0 > > 20/01/2014 17:42:51 [Insteon PLM] data recieved b(�\▒/� > 20/01/2014 17:42:51 [Insteon_PLM] DEBUG3: Received PLM raw data: > 026228f55c1a2f0000000000010000000000000000d006 > 20/01/2014 17:42:51 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 1a > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 2f0000000000010000000000000000d0 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00000000010000000000000000d006 > PLM Response: (06) ACK > > 20/01/2014 17:42:51 [Insteon_PLM] DEBUG3: Received PLM acknowledge: > obj=$l_front_porch; command=read_write_aldb; > extra=000000000001000000000000000000 > 20/01/2014 17:42:51 [Insteon PLM] data recieved P(�\ �V"/ > 20/01/2014 17:42:51 [Insteon_PLM] DEBUG3: Received PLM raw data: > 025028f55c20d956222f00 > 20/01/2014 17:42:51 [Insteon_PLM] DEBUG4: > PLM Command: (0250) insteon_received > From Address: 28:f5:5c > To Address: 20:d9:56 > Message Flags: 22 > Message Type: (001) ACK of Direct Message > Message Length: (0) Standard Length > Hops Left: 0 > Max Hops: 2 > Insteon Message: 2f00 > Cmd 1: (2f) Light OFF at Ramp Rate > Cmd 2: (00) Ramp Rate > > 20/01/2014 17:42:51 [Insteon::BaseInterface] DEBUG3: PLM > command:insteon_received; Device command:read_write_aldb; type:direct; > group: > 20/01/2014 17:42:51 [Insteon::BaseObject] DEBUG3: Adding hop count of 2 > to hop_array of $l_front_porch > 20/01/2014 17:42:51 [Insteon::BaseObject] DEBUG4: > $l_front_porch->default_hop_count()=2 :: hop_array[]=2123133322 > 20/01/2014 17:42:51 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0000] > received: 00 for _mem_activity=scan _mem_action=aldb_i2read > 20/01/2014 17:42:51 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0000] > received ack > 20/01/2014 17:42:52 [Insteon PLM] data recieved Q(�\ �V/�� �Vh > 20/01/2014 17:42:52 [Insteon_PLM] DEBUG3: Received PLM raw data: > 025128f55c20d956112f0000010fff00ea0120d956031c0168 > 20/01/2014 17:42:52 [Insteon_PLM] DEBUG4: > PLM Command: (0251) insteon_ext_received > From Address: 28:f5:5c > To Address: 20:d9:56 > Message Flags: 11 > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 0 > Max Hops: 1 > Insteon Message: 2f0000010fff00ea0120d956031c0168 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00010fff00ea0120d956031c0168 > > 20/01/2014 17:42:52 [Insteon::BaseInterface] DEBUG3: Message received > with 0 hops left, plus ACK will take 1 to deliver, delaying next transmit > by 250 milliseconds to avoid collisions. > 20/01/2014 17:42:52 [Insteon::BaseInterface] DEBUG: PLM > command:insteon_ext_received; Device command:read_write_aldb; type:direct; > group: > 20/01/2014 17:42:52 [Insteon::BaseInterface] Processing message for > $l_front_porch > 20/01/2014 17:42:52 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 > to hop_array of $l_front_porch > 20/01/2014 17:42:52 [Insteon::BaseObject] DEBUG4: > $l_front_porch->default_hop_count()=2 :: hop_array[]=1212313332 > 20/01/2014 17:42:52 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0000] > received: 0000010fff00ea0120d956031c0168 for _mem_activity=scan > _mem_action=aldb_i2readack > 20/01/2014 17:42:52 [Insteon::ALDB_i2] DEBUG4: Start of scan; > initializing aldb structure > 20/01/2014 17:42:52 [Insteon::ALDB_i2] DEBUG4: active link found; adding > address [0fff] to aldb > 20/01/2014 17:42:52 [Insteon::ALDB_i2] $l_front_porch reading ALDB at > location: 0x0ff7 > 20/01/2014 17:42:52 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=read_write_aldb; extra=0000000ff701000000000000000000 incurred > delay of 0.26 seconds; starting hop-count: 2 > 20/01/2014 17:42:52 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=read_write_aldb; extra=0000000ff701000000000000000000 incurred > delay of 0.26 seconds; starting hop-count: 2 > 20/01/2014 17:42:52 [Insteon_PLM] DEBUG3: Sending PLM raw data: > 026228f55c1a2f0000000ff7010000000000000000ca > 20/01/2014 17:42:52 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 1a > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 2f0000000ff7010000000000000000ca > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00000ff7010000000000000000ca > > 20/01/2014 17:42:52 [Insteon PLM] data recieved b(�\▒/�� > 20/01/2014 17:42:52 [Insteon_PLM] DEBUG3: Received PLM raw data: > 026228f55c1a2f0000000ff7010000000000000000ca06 > 20/01/2014 17:42:52 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 1a > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 2f0000000ff7010000000000000000ca > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00000ff7010000000000000000ca06 > PLM Response: (06) ACK > > 20/01/2014 17:42:52 [Insteon_PLM] DEBUG3: Received PLM acknowledge: > obj=$l_front_porch; command=read_write_aldb; > extra=0000000ff701000000000000000000 > 20/01/2014 17:42:52 [Insteon PLM] data recieved P(�\ �V&/ > 20/01/2014 17:42:52 [Insteon_PLM] DEBUG3: Received PLM raw data: > 025028f55c20d956262f00 > 20/01/2014 17:42:52 [Insteon_PLM] DEBUG4: > PLM Command: (0250) insteon_received > From Address: 28:f5:5c > To Address: 20:d9:56 > Message Flags: 26 > Message Type: (001) ACK of Direct Message > Message Length: (0) Standard Length > Hops Left: 1 > Max Hops: 2 > Insteon Message: 2f00 > Cmd 1: (2f) Light OFF at Ramp Rate > Cmd 2: (00) Ramp Rate > > 20/01/2014 17:42:52 [Insteon::BaseInterface] DEBUG3: Message received > with 1 hops left, delaying next transmit by 150 milliseconds to avoid > collisions. > 20/01/2014 17:42:52 [Insteon::BaseInterface] DEBUG3: PLM > command:insteon_received; Device command:read_write_aldb; type:direct; > group: > 20/01/2014 17:42:52 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 > to hop_array of $l_front_porch > 20/01/2014 17:42:52 [Insteon::BaseObject] DEBUG4: > $l_front_porch->default_hop_count()=2 :: hop_array[]=1121231333 > 20/01/2014 17:42:52 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0ff7] > received: 00 for _mem_activity=scan _mem_action=aldb_i2read > 20/01/2014 17:42:52 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0ff7] > received ack > 20/01/2014 17:42:53 [Insteon PLM] data recieved Q(�\ �V/�� �V�� > 20/01/2014 17:42:53 [Insteon_PLM] DEBUG3: Received PLM raw data: > 025128f55c20d956112f0000010ff700aa0020d956ff1c01b5 > 20/01/2014 17:42:53 [Insteon_PLM] DEBUG4: > PLM Command: (0251) insteon_ext_received > From Address: 28:f5:5c > To Address: 20:d9:56 > Message Flags: 11 > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 0 > Max Hops: 1 > Insteon Message: 2f0000010ff700aa0020d956ff1c01b5 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00010ff700aa0020d956ff1c01b5 > > 20/01/2014 17:42:53 [Insteon::BaseInterface] DEBUG3: Message received > with 0 hops left, plus ACK will take 1 to deliver, delaying next transmit > by 250 milliseconds to avoid collisions. > 20/01/2014 17:42:53 [Insteon::BaseInterface] DEBUG: PLM > command:insteon_ext_received; Device command:read_write_aldb; type:direct; > group: > 20/01/2014 17:42:53 [Insteon::BaseInterface] Processing message for > $l_front_porch > 20/01/2014 17:42:53 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 > to hop_array of $l_front_porch > 20/01/2014 17:42:53 [Insteon::BaseObject] DEBUG4: > $l_front_porch->default_hop_count()=2 :: hop_array[]=1112123133 > 20/01/2014 17:42:53 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0ff7] > received: 0000010ff700aa0020d956ff1c01b5 for _mem_activity=scan > _mem_action=aldb_i2readack > 20/01/2014 17:42:53 [Insteon::ALDB_i2] DEBUG4: active link found; adding > address [0ff7] to aldb > 20/01/2014 17:42:53 [Insteon::ALDB_i2] $l_front_porch reading ALDB at > location: 0x0fef > 20/01/2014 17:42:53 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=read_write_aldb; extra=0000000fef01000000000000000000 incurred > delay of 0.26 seconds; starting hop-count: 2 > 20/01/2014 17:42:53 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=read_write_aldb; extra=0000000fef01000000000000000000 incurred > delay of 0.26 seconds; starting hop-count: 2 > 20/01/2014 17:42:53 [Insteon_PLM] DEBUG3: Sending PLM raw data: > 026228f55c1a2f0000000fef010000000000000000d2 > 20/01/2014 17:42:53 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 1a > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 2f0000000fef010000000000000000d2 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00000fef010000000000000000d2 > > 20/01/2014 17:42:53 [Insteon PLM] data recieved b(�\▒/�� > 20/01/2014 17:42:53 [Insteon_PLM] DEBUG3: Received PLM raw data: > 026228f55c1a2f0000000fef010000000000000000d206 > 20/01/2014 17:42:53 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 1a > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 2f0000000fef010000000000000000d2 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00000fef010000000000000000d206 > PLM Response: (06) ACK > > 20/01/2014 17:42:53 [Insteon_PLM] DEBUG3: Received PLM acknowledge: > obj=$l_front_porch; command=read_write_aldb; > extra=0000000fef01000000000000000000 > 20/01/2014 17:42:55 [Insteon PLM] data recieved Q(�\ �V/�� > 20/01/2014 17:42:55 [Insteon_PLM] DEBUG3: Received PLM raw data: > 025128f55c20d956172f0000010fef000000000000000000d2 > 20/01/2014 17:42:55 [Insteon_PLM] DEBUG4: > PLM Command: (0251) insteon_ext_received > From Address: 28:f5:5c > To Address: 20:d9:56 > Message Flags: 17 > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 1 > Max Hops: 3 > Insteon Message: 2f0000010fef000000000000000000d2 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00010fef000000000000000000d2 > > 20/01/2014 17:42:55 [Insteon::BaseInterface] DEBUG3: Message received > with 1 hops left, plus ACK will take 3 to deliver, delaying next transmit > by 850 milliseconds to avoid collisions. > 20/01/2014 17:42:55 [Insteon::BaseInterface] DEBUG: PLM > command:insteon_ext_received; Device command:read_write_aldb; type:direct; > group: > 20/01/2014 17:42:55 [Insteon::BaseInterface] Processing message for > $l_front_porch > 20/01/2014 17:42:55 [Insteon::BaseObject] DEBUG3: Adding hop count of 2 > to hop_array of $l_front_porch > 20/01/2014 17:42:55 [Insteon::BaseObject] DEBUG4: > $l_front_porch->default_hop_count()=2 :: hop_array[]=2111212313 > 20/01/2014 17:42:55 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0fef] > received: 0000010fef000000000000000000d2 for _mem_activity=scan > _mem_action=aldb_i2read > 20/01/2014 17:42:55 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0fef] > ack not received. ignoring message > 20/01/2014 17:42:56 [Insteon::BaseMessage] WARN: now resending > obj=$l_front_porch; command=read_write_aldb; > extra=0000000fef01000000000000000000 after 1 attempts. > 20/01/2014 17:42:56 [Insteon::BaseObject] DEBUG3: Adding hop count of 3 > to hop_array of $l_front_porch > 20/01/2014 17:42:56 [Insteon::BaseObject] DEBUG4: > $l_front_porch->default_hop_count()=2 :: hop_array[]=3211121231 > 20/01/2014 17:42:56 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=read_write_aldb; extra=0000000fef01000000000000000000 incurred > delay of 3.26 seconds; starting hop-count: 2 > 20/01/2014 17:42:56 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=read_write_aldb; extra=0000000fef01000000000000000000 incurred > delay of 3.26 seconds; starting hop-count: 2 > 20/01/2014 17:42:56 [Insteon_PLM] DEBUG3: Sending PLM raw data: > 026228f55c1a2f0000000fef010000000000000000d2 > 20/01/2014 17:42:56 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 1a > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 2f0000000fef010000000000000000d2 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00000fef010000000000000000d2 > > 20/01/2014 17:42:56 [Insteon PLM] data recieved b(�\▒/�� > 20/01/2014 17:42:56 [Insteon_PLM] DEBUG3: Received PLM raw data: > 026228f55c1a2f0000000fef010000000000000000d206 > 20/01/2014 17:42:56 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 1a > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 2f0000000fef010000000000000000d2 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00000fef010000000000000000d206 > PLM Response: (06) ACK > > 20/01/2014 17:42:56 [Insteon_PLM] DEBUG3: Received PLM acknowledge: > obj=$l_front_porch; command=read_write_aldb; > extra=0000000fef01000000000000000000 > 20/01/2014 17:42:59 [Insteon::BaseMessage] WARN: now resending > obj=$l_front_porch; command=read_write_aldb; > extra=0000000fef01000000000000000000 after 2 attempts. > 20/01/2014 17:42:59 [Insteon::BaseObject] DEBUG3: Adding hop count of 3 > to hop_array of $l_front_porch > 20/01/2014 17:42:59 [Insteon::BaseObject] DEBUG4: > $l_front_porch->default_hop_count()=2 :: hop_array[]=3321112123 > 20/01/2014 17:42:59 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=read_write_aldb; extra=0000000fef01000000000000000000 incurred > delay of 6.27 seconds; starting hop-count: 2 > 20/01/2014 17:42:59 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=read_write_aldb; extra=0000000fef01000000000000000000 incurred > delay of 6.27 seconds; starting hop-count: 2 > 20/01/2014 17:42:59 [Insteon_PLM] DEBUG3: Sending PLM raw data: > 026228f55c1a2f0000000fef010000000000000000d2 > 20/01/2014 17:42:59 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 1a > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 2f0000000fef010000000000000000d2 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00000fef010000000000000000d2 > > 20/01/2014 17:42:59 [Insteon PLM] data recieved b(�\▒/�� > 20/01/2014 17:42:59 [Insteon_PLM] DEBUG3: Received PLM raw data: > 026228f55c1a2f0000000fef010000000000000000d206 > 20/01/2014 17:42:59 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 1a > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 2f0000000fef010000000000000000d2 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00000fef010000000000000000d206 > PLM Response: (06) ACK > > 20/01/2014 17:42:59 [Insteon_PLM] DEBUG3: Received PLM acknowledge: > obj=$l_front_porch; command=read_write_aldb; > extra=0000000fef01000000000000000000 > 20/01/2014 17:42:59 [Insteon PLM] data recieved P(�\ �V"/ > 20/01/2014 17:42:59 [Insteon_PLM] DEBUG3: Received PLM raw data: > 025028f55c20d956222f00 > 20/01/2014 17:42:59 [Insteon_PLM] DEBUG4: > PLM Command: (0250) insteon_received > From Address: 28:f5:5c > To Address: 20:d9:56 > Message Flags: 22 > Message Type: (001) ACK of Direct Message > Message Length: (0) Standard Length > Hops Left: 0 > Max Hops: 2 > Insteon Message: 2f00 > Cmd 1: (2f) Light OFF at Ramp Rate > Cmd 2: (00) Ramp Rate > > 20/01/2014 17:42:59 [Insteon::BaseInterface] DEBUG3: PLM > command:insteon_received; Device command:read_write_aldb; type:direct; > group: > 20/01/2014 17:42:59 [Insteon::BaseObject] DEBUG3: Adding hop count of 2 > to hop_array of $l_front_porch > 20/01/2014 17:42:59 [Insteon::BaseObject] DEBUG4: > $l_front_porch->default_hop_count()=2 :: hop_array[]=2332111212 > 20/01/2014 17:42:59 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0fef] > received: 00 for _mem_activity=scan _mem_action=aldb_i2read > 20/01/2014 17:42:59 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0fef] > received ack > 20/01/2014 17:43:00 [Insteon PLM] data recieved Q(�\ �V/�� > 20/01/2014 17:43:00 [Insteon_PLM] DEBUG3: Received PLM raw data: > 025128f55c20d956112f0000010fef000000000000000000d2 > 20/01/2014 17:43:00 [Insteon_PLM] DEBUG4: > PLM Command: (0251) insteon_ext_received > From Address: 28:f5:5c > To Address: 20:d9:56 > Message Flags: 11 > Message Type: (000) Direct Message > Message Length: (1) Extended Length > Hops Left: 0 > Max Hops: 1 > Insteon Message: 2f0000010fef000000000000000000d2 > Cmd 1: (2f) Read/Write ALL-Link Database > Cmd 2: (00) Command in D2 > D1-D14: 00010fef000000000000000000d2 > > 20/01/2014 17:43:00 [Insteon::BaseInterface] DEBUG3: Message received > with 0 hops left, plus ACK will take 1 to deliver, delaying next transmit > by 250 milliseconds to avoid collisions. > 20/01/2014 17:43:00 [Insteon::BaseInterface] DEBUG: PLM > command:insteon_ext_received; Device command:read_write_aldb; type:direct; > group: > 20/01/2014 17:43:00 [Insteon::BaseInterface] Processing message for > $l_front_porch > 20/01/2014 17:43:00 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 > to hop_array of $l_front_porch > 20/01/2014 17:43:00 [Insteon::BaseObject] DEBUG4: > $l_front_porch->default_hop_count()=2 :: hop_array[]=1233211121 > 20/01/2014 17:43:00 [Insteon::ALDB_i2] DEBUG3: $l_front_porch [0x0fef] > received: 0000010fef000000000000000000d2 for _mem_activity=scan > _mem_action=aldb_i2readack > 20/01/2014 17:43:00 [Insteon::ALDB_i2] DEBUG4: scan done; adding last > address [0fef] to empty array > 20/01/2014 17:43:00 [Insteon::ALDB_i2] $l_front_porch completed link > memory scan: status: good > 20/01/2014 17:43:00 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=status_request incurred delay of 0.26 seconds; starting hop-count: 2 > 20/01/2014 17:43:00 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=status_request incurred delay of 0.26 seconds; starting hop-count: 2 > 20/01/2014 17:43:00 [Insteon_PLM] DEBUG3: Sending PLM raw data: > 026228f55c0a1900 > 20/01/2014 17:43:00 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 0a > Message Type: (000) Direct Message > Message Length: (0) Standard Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 1900 > Cmd 1: (19) Light Status Request > Cmd 2: (00) On Level > > 20/01/2014 17:43:00 [Insteon PLM] data recieved b(�\ > > 20/01/2014 17:43:00 [Insteon_PLM] DEBUG3: Received PLM raw data: > 026228f55c0a190006 > 20/01/2014 17:43:00 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 0a > Message Type: (000) Direct Message > Message Length: (0) Standard Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 1900 > Cmd 1: (19) Light Status Request > Cmd 2: (00) On Level > PLM Response: (06) ACK > > 20/01/2014 17:43:00 [Insteon_PLM] DEBUG3: Received PLM acknowledge: > obj=$l_front_porch; command=status_request > 20/01/2014 17:43:02 [Insteon::BaseMessage] WARN: now resending > obj=$l_front_porch; command=status_request after 1 attempts. > 20/01/2014 17:43:02 [Insteon::BaseObject] DEBUG3: Adding hop count of 3 > to hop_array of $l_front_porch > 20/01/2014 17:43:02 [Insteon::BaseObject] DEBUG4: > $l_front_porch->default_hop_count()=2 :: hop_array[]=3123321112 > 20/01/2014 17:43:02 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=status_request incurred delay of 2.17 seconds; starting hop-count: 2 > 20/01/2014 17:43:02 [Insteon_PLM] DEBUG2: Sending obj=$l_front_porch; > command=status_request incurred delay of 2.17 seconds; starting hop-count: 2 > 20/01/2014 17:43:02 [Insteon_PLM] DEBUG3: Sending PLM raw data: > 026228f55c0a1900 > 20/01/2014 17:43:02 [Insteon_PLM] DEBUG4: > PLM Command: (0262) insteon_send > To Address: 28:f5:5c > Message Flags: 0a > Message Type: (000) Direct Message > Message Length: (0) Standard Length > Hops Left: 2 > Max Hops: 2 > Insteon Message: 1900 > Cmd 1: (19) Light Status Request > Cmd 2: (00) On Level > > 20/01/2014 17:43:02 [Insteon PLM] data recieved > 20/01/2014 17:43:02 [Insteon_PLM] DEBUG3: Received PLM raw data: 1515 > 20/01/2014 17:43:02 [Insteon_PLM] DEBUG3: Interface extremely busy. > Resending command after delaying for 1 second > 20/01/2014 17:43:02 [Insteon PLM] data recieved P(�\ �V+� > 20/01/2014 17:43:02 [Insteon_PLM] DEBUG3: Received PLM raw data: > 025028f55c20d9562b03ff > 20/01/2014 17:43:02 [Insteon_PLM] DEBUG4: > PLM Command: (0250) insteon_received > From Address: 28:f5:5c > To Address: 20:d9:56 > Message Flags: 2b > Message Type: (001) ACK of Direct Message > Message Length: (0) Standard Length > Hops Left: 2 > Max Hops: 3 > Insteon Message: 03ff > Cmd 1: (03) Device Request > Cmd 2: (ff) > > 20/01/2014 17:43:02 [Insteon::BaseInterface] DEBUG3: Message received > with 2 hops left, delaying next transmit by 250 milliseconds to avoid > collisions. > 20/01/2014 17:43:02 [Insteon::BaseInterface] DEBUG3: PLM > command:insteon_received; Device command:; type:direct; group: > 20/01/2014 17:43:02 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 > to hop_array of $l_front_porch > 20/01/2014 17:43:02 [Insteon::BaseObject] DEBUG4: > $l_front_porch->default_hop_count()=2 :: hop_array[]=1312332111 > 20/01/2014 17:43:02 [Insteon::BaseObject] received status for > $l_front_porch with on-level: 100%, hops left: 2 > 20/01/2014 17:43:02 [Insteon::BaseObject] > $l_front_porch::set_receive(100%, $PLM) > 20/01/2014 17:43:02 [Insteon::BaseObject] The Link Table Version for > $l_front_porch has been updated to version number 03 > 20/01/2014 17:43:02 [Insteon::AllLinkDatabase] Link table for > $l_front_porch health: good > > > On 01/20/2014 03:28 PM, Kevin Robert Keegan wrote: > > Interesting, > > George, can you try and run things with debug set to Insteon:4. Using > level 4 ought to result in nicely formatted decoded messages in the print > log, negating the need for the wireshark log. > > It is hard to say what is going on, it is possible that the timing just > needs to be increased. At the moment, there is nothing in the code that > would increase the delay for all messages across the board. There are two > ways you can kinda hack a delay in for the time being: > > 1. In your ini file set Insteon_PLM_xmit_delay to something like 1 > second. The default is .25. This will slow MH down so that it can only > send an insteon message to the PLM once a second. > > 2. For each insteon object you can set a timeout factor, so > $object->timeout_factor(1.5) would add a 50% increase to the message > transmission delay. You would have to do this on every device. > > Of course if these turn out to be solutions, we can certainly gin up a > global setting for you. > > > On Sat, Jan 18, 2014 at 12:15 PM, George Clark <ge...@fe...>wrote: > >> Hi all, >> >> I've re-applied the TCP patch against the latest Insteon_PLM code. >> Basic functionality works well. I'm able to control devices via >> misterhouse and the PLM. This includes both Insteon and X10 devices. >> However some device requests fail with retries. I suspect that it's >> an issue in the IP changes and receiving information from the device. >> >> I wonder if the original author ever got these functions working for IP, >> or if there were existing issues. For the requests that work, I see >> some retransmissions occurring, so there may be some timing issues, >> even though the PLM responded. >> >> Here are the logs, following by a wireshark hex dump of the payloads. >> These first two commands work but with (unnecessary?) retransmissions. >> >> 18/01/2014 14:41:55 Running: l garage status >> 18/01/2014 14:41:57 [Insteon::BaseMessage] WARN: now resending >> obj=$l_garage; command=status_request after 1 attempts. >> 18/01/2014 14:41:57 [Insteon::BaseObject] received status for $l_garage >> with on-level: 0%, hops left: 2 >> 18/01/2014 14:41:57 [Insteon::BaseObject] $l_garage::set_receive(off, >> $PLM) >> >> 00000000 02 62 28 7a f2 0a 19 00 .b(z.... >> 00000000 02 62 28 7a f2 0a 19 00 06 .b(z.... . >> 00000008 02 62 28 7a f2 0a 19 00 .b(z.... >> 00000009 15 . >> 0000000A 02 50 28 7a f2 20 d9 56 2b 00 00 .P(z. .V >> +.. >> >> >> 18/01/2014 14:47:14 Running: l garage get engine version >> 18/01/2014 14:47:16 [Insteon::BaseMessage] WARN: now resending >> obj=$l_garage; command=get_engine_version after 1 attempts. >> 18/01/2014 14:47:16 [Insteon::BaseObject] received engine version for >> $l_garage of I2CS. hops left: 2 >> >> >> 00000010 02 62 28 7a f2 0a 0d 00 .b(z.... >> 00000015 02 62 28 7a f2 0a 0d 00 06 .b(z.... . >> 00000018 02 62 28 7a f2 0a 0d 00 .b(z.... >> 0000001E 15 . >> 0000001F 02 50 28 7a f2 20 d9 56 2b 0d 02 .P(z. .V >> +.. >> >> >> Here is where it goes wrong. It appears that Insteon_PLM TCP version >> somehow fails to receive / decode the response to the scan link table. >> I guess I need to dig down into the code and callback routines to figure >> out why this is failing. I'm not sure where to begin to look. >> >> 18/01/2014 14:48:42 Running: l garage scan link table >> 18/01/2014 14:48:42 [Insteon::ALDB_i2] $l_garage reading ALDB at >> location: 0x0000 >> 18/01/2014 14:48:44 [Insteon::BaseInterface] DEBUG: PLM >> command:insteon_ext_received; Device command:read_write_aldb; >> type:direct; group: >> 18/01/2014 14:48:44 [Insteon::ALDB_i2] $l_garage reading ALDB at >> location: 0x0ff7 >> 18/01/2014 14:48:47 [Insteon::BaseMessage] WARN: now resending >> obj=$l_garage; command=read_write_aldb; >> extra=0000000ff701000000000000000000 after 1 attempts. >> 18/01/2014 14:48:50 [Insteon::BaseMessage] WARN: now resending >> obj=$l_garage; command=read_write_aldb; >> extra=0000000ff701000000000000000000 after 2 attempts. >> 18/01/2014 14:48:53 [Insteon::BaseMessage] WARN: now resending >> obj=$l_garage; command=read_write_aldb; >> extra=0000000ff701000000000000000000 after 3 attempts. >> 18/01/2014 14:48:56 [Insteon::BaseMessage] WARN: now resending >> obj=$l_garage; command=read_write_aldb; >> extra=0000000ff701000000000000000000 after 4 attempts. >> 18/01/2014 14:48:57 [Insteon::BaseInterface] DEBUG: PLM >> command:insteon_ext_received; Device command:read_write_aldb; >> type:direct; group: >> 18/01/2014 14:48:57 [Insteon::ALDB_i2] $l_garage reading ALDB at >> location: 0x0fef >> 18/01/2014 14:49:01 [Insteon::BaseMessage] WARN: now resending >> obj=$l_garage; command=read_write_aldb; >> extra=0000000fef01000000000000000000 after 1 attempts. >> 18/01/2014 14:49:02 [Insteon::BaseMessage] WARN: now resending >> obj=$l_garage; command=read_write_aldb; >> extra=0000000fef01000000000000000000 after 2 attempts. >> 18/01/2014 14:49:02 [Insteon::BaseMessage] Hop count not increased for >> $l_garage because no_hop_increase flag was set. >> 18/01/2014 14:49:05 [Insteon::BaseMessage] WARN: now resending >> obj=$l_garage; command=read_write_aldb; >> extra=0000000fef01000000000000000000 after 3 attempts. >> 18/01/2014 14:49:08 [Insteon::BaseMessage] WARN: now resending >> obj=$l_garage; command=read_write_aldb; >> extra=0000000fef01000000000000000000 after 4 attempts. >> 18/01/2014 14:49:09 [Insteon::BaseInterface] WARN: number of retries >> (5) for obj=$l_garage; command=read_write_aldb; >> extra=0000000fef01000000000000000000 exceeds limit. Now moving on... >> >> >> >> 00000020 02 62 28 7a f2 1a 2f 00 00 00 00 00 01 00 00 00 .b(z../. >> ........ >> 00000030 00 00 00 00 00 d0 ...... >> 0000002A 02 62 28 7a f2 1a 2f 00 00 00 00 00 01 00 00 00 .b(z../. >> ........ >> 0000003A 00 00 00 00 00 d0 06 ....... >> 00000041 02 50 28 7a f2 20 d9 56 26 2f 00 .P(z. .V >> &/. >> 0000004C 02 51 28 7a f2 20 d9 56 12 2f 00 00 01 0f ff 00 .Q(z. .V >> ./...... >> 0000005C a2 00 20 d9 56 ff 1f 01 b2 .. .V... . >> 00000036 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. >> ........ >> 00000046 00 00 00 00 00 ca ...... >> 00000065 02 . >> 00000066 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 b(z../.. >> ....... >> 00000075 00 00 00 00 00 ca 06 ....... >> 0000004C 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. >> ........ >> 0000005C 00 00 00 00 00 ca ...... >> 0000007C 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. >> ........ >> 0000008C 00 00 00 00 00 ca 06 ....... >> 00000093 02 50 28 7a f2 20 d9 56 2b 2f 00 .P(z. .V >> +/. >> 00000062 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. >> ........ >> 00000072 00 00 00 00 00 ca ...... >> 0000009E 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. >> ........ >> 000000AE 00 00 00 00 00 ca 06 ....... >> 00000078 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. >> ........ >> 00000088 00 00 00 00 00 ca ...... >> 000000B5 02 62 28 .b( >> 000000B8 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 00 00 00 z../.... >> ........ >> 000000C8 00 00 ca 06 .... >> 0000008E 02 62 28 7a f2 1a 2f 00 00 00 0f f7 01 00 00 00 .b(z../. >> ........ >> 0000009E 00 00 00 00 00 ca ...... >> 000000CC 15 15 .. >> 000000CE 02 51 28 7a f2 20 d9 56 12 2f 00 00 01 0f f7 00 .Q(z. .V >> ./...... >> 000000DE 22 00 20 d9 56 ff 1f 01 3a ". .V... : >> 000000A4 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. >> ........ >> 000000B4 00 00 00 00 00 d2 ...... >> 000000E7 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. >> ........ >> 000000F7 00 00 00 00 00 d2 06 ....... >> 000000BA 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. >> ........ >> 000000CA 00 00 00 00 00 d2 ...... >> 000000FE 15 15 .. >> 000000D0 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. >> ........ >> 000000E0 00 00 00 00 00 d2 ...... >> 00000100 02 62 28 7a f2 1a 2f 00 00 00 0f ef 01 00 00 00 .b(z../. >> ........ >> 00000110 00 00 00 00 00 d2 06 ....... >> 00000117 02 50 28 7a f2 20 d9 56 26 2f 00 .P(z. .V >> &/. >> >> >> >> >> ------------------------------------------------------------------------------ >> CenturyLink Cloud: The Leader in Enterprise Cloud Services. >> Learn Why More Businesses Are Choosing CenturyLink Cloud For >> Critical Workloads, Development Environments & Everything In Between. >> Get a Quote or Start a Free Trial Today. >> >> http://pubads.g.doubleclick.net/gampad/clk?id=119420431&iu=/4140/ostg.clktrk >> ________________________________________________________ >> To unsubscribe from this list, go to: >> http://sourceforge.net/mail/?group_id=1365 >> >> > > |
From: George C. <ge...@fe...> - 2014-01-21 00:58:56
|
Hi Kevin, Bad news ... Crashed Can't call method "setby" on an undefined value at /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm line 930. at mh line 31. main::__ANON__("Can't call method \"setby\" on an undefined value at /home/gac/"...) called at /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm line 930 Insteon_PLM::_parse_data(Insteon_PLM=HASH(0x9816fd8), "025806025028f55c20d956611341") called at /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm line 264 Insteon_PLM::check_for_data(Insteon_PLM=HASH(0x9816fd8)) called at /home/gac/automation/misterhouse/bin/../lib/Insteon/BaseInterface.pm line 33 Insteon::BaseInterface::check_for_data() called at mh line 1409 main::run_hooks_("MainLoop_pre") called at (eval 87) line 5 main::MainLoop_pre_hooks() called at mh line 1522 main::check_for_action called at mh line 3303 main::monitor_commands called at mh line 6724 It took me a bit, I had never set up any scenes on the 2540N, so I had to figure that out. Not particularly intuitive, but done. As soon as I click on or off for the scene using the web interface on the 2540N, mh dies. Line messages are not going line up for you due to the IP changes, so here is the context: else { my $message_to_string = ($self->active_message) ? $self->active_message->to_string() : ""; &::print_log("[Insteon_PLM] Received all-link cleanup success: $message_to_string") if $self->active_message->setby->debuglevel(1, 'insteon'); if (ref $self->active_message && ref $self->active_message->setby){ <======= Line 930 my $object = $self->active_message->setby; $object->is_acknowledged(1); $object->_process_command_stack(); } $self->clear_active_message(); George On 01/20/2014 07:42 PM, Kevin Robert Keegan wrote: > Sorry, yes use the web interface built into the hub to change a device > state. > > I figure some people would be interested in using the hub as a "Wife > Acceptable Interface" while using MH as the more robust backend. > > Kevin > > > On Mon, Jan 20, 2014 at 4:40 PM, George Clark <ge...@fe... > <mailto:ge...@fe...>> wrote: > > Hi Kevin, > > I'm glad to test, but I'm not sure what you mean by use the hub to > control an object? > > You mean use the http connection to the 2540N to change a devices > state > while mh is connected to the modem port? > > On 01/20/2014 07:36 PM, Kevin Robert Keegan wrote: > > Can you test one thing for me? I would like to know what > happens when > > you use the hub to control an object. What does MH do if anything? > > Does it recognize the change? Does it implode when it receives an > > acknowledgement to a command that it never sent? I could inject > some > > fake messages, but I figure it would be easier for you to test > it out. > > > > |
From: Kevin R. K. <ke...@kr...> - 2014-01-21 01:14:38
|
Awesome, thanks for doing that. We never coded MH with this in mind, so it isn't really all that surprising. Just curious to see what would happen. I can easily patch that issue, but I suspect there are many more. On Mon, Jan 20, 2014 at 4:58 PM, George Clark <ge...@fe...> wrote: > Hi Kevin, > > Bad news ... Crashed > > Can't call method "setby" on an undefined value at > /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm line 930. > at mh line 31. > main::__ANON__("Can't call method \"setby\" on an undefined value > at /home/gac/"...) called at > /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm line 930 > Insteon_PLM::_parse_data(Insteon_PLM=HASH(0x9816fd8), > "025806025028f55c20d956611341") called at > /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm line 264 > Insteon_PLM::check_for_data(Insteon_PLM=HASH(0x9816fd8)) called at > /home/gac/automation/misterhouse/bin/../lib/Insteon/BaseInterface.pm line 33 > Insteon::BaseInterface::check_for_data() called at mh line 1409 > main::run_hooks_("MainLoop_pre") called at (eval 87) line 5 > main::MainLoop_pre_hooks() called at mh line 1522 > main::check_for_action called at mh line 3303 > main::monitor_commands called at mh line 6724 > > It took me a bit, I had never set up any scenes on the 2540N, so I had > to figure that out. Not particularly intuitive, but done. As soon as I > click on or off for the scene using the web interface on the 2540N, mh > dies. > > Line messages are not going line up for you due to the IP changes, so here > is the context: > > else > { > my $message_to_string = > ($self->active_message) ? $self->active_message->to_string() : ""; > &::print_log("[Insteon_PLM] Received all-link cleanup > success: $message_to_string") > if > $self->active_message->setby->debuglevel(1, 'insteon'); > if (ref $self->active_message && ref > $self->active_message->setby){ <======= Line 930 > my $object = $self->active_message->setby; > $object->is_acknowledged(1); > $object->_process_command_stack(); > } > $self->clear_active_message(); > > > George > > > > On 01/20/2014 07:42 PM, Kevin Robert Keegan wrote: > > Sorry, yes use the web interface built into the hub to change a device > state. > > I figure some people would be interested in using the hub as a "Wife > Acceptable Interface" while using MH as the more robust backend. > > Kevin > > > On Mon, Jan 20, 2014 at 4:40 PM, George Clark <ge...@fe...>wrote: > >> Hi Kevin, >> >> I'm glad to test, but I'm not sure what you mean by use the hub to >> control an object? >> >> You mean use the http connection to the 2540N to change a devices state >> while mh is connected to the modem port? >> >> On 01/20/2014 07:36 PM, Kevin Robert Keegan wrote: >> > Can you test one thing for me? I would like to know what happens when >> > you use the hub to control an object. What does MH do if anything? >> > Does it recognize the change? Does it implode when it receives an >> > acknowledgement to a command that it never sent? I could inject some >> > fake messages, but I figure it would be easier for you to test it out. >> > >> >> > > |
From: Kevin R. K. <ke...@kr...> - 2014-02-03 23:50:29
|
George, Based on you success using the InsteonIP code, I brought it up-to-date with the Master branch. I also added some code that should prevent MH from crashing when the hub is used to control any insteon objects. If you have a chance test out the code and let me know if it works: https://github.com/krkeegan/misterhouse/tree/InsteonIP If it seems to go alright, we can merge it into Master. Kevin On Mon, Jan 20, 2014 at 5:14 PM, Kevin Robert Keegan <ke...@kr...>wrote: > Awesome, thanks for doing that. > > We never coded MH with this in mind, so it isn't really all that > surprising. Just curious to see what would happen. > > I can easily patch that issue, but I suspect there are many more. > > > On Mon, Jan 20, 2014 at 4:58 PM, George Clark <ge...@fe...>wrote: > >> Hi Kevin, >> >> Bad news ... Crashed >> >> Can't call method "setby" on an undefined value at >> /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm line 930. >> at mh line 31. >> main::__ANON__("Can't call method \"setby\" on an undefined value >> at /home/gac/"...) called at >> /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm line 930 >> Insteon_PLM::_parse_data(Insteon_PLM=HASH(0x9816fd8), >> "025806025028f55c20d956611341") called at >> /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm line 264 >> Insteon_PLM::check_for_data(Insteon_PLM=HASH(0x9816fd8)) called >> at /home/gac/automation/misterhouse/bin/../lib/Insteon/BaseInterface.pm >> line 33 >> Insteon::BaseInterface::check_for_data() called at mh line 1409 >> main::run_hooks_("MainLoop_pre") called at (eval 87) line 5 >> main::MainLoop_pre_hooks() called at mh line 1522 >> main::check_for_action called at mh line 3303 >> main::monitor_commands called at mh line 6724 >> >> It took me a bit, I had never set up any scenes on the 2540N, so I had >> to figure that out. Not particularly intuitive, but done. As soon as I >> click on or off for the scene using the web interface on the 2540N, mh >> dies. >> >> Line messages are not going line up for you due to the IP changes, so >> here is the context: >> >> else >> { >> my $message_to_string = >> ($self->active_message) ? $self->active_message->to_string() : ""; >> &::print_log("[Insteon_PLM] Received all-link cleanup >> success: $message_to_string") >> if >> $self->active_message->setby->debuglevel(1, 'insteon'); >> if (ref $self->active_message && ref >> $self->active_message->setby){ <======= Line 930 >> my $object = $self->active_message->setby; >> $object->is_acknowledged(1); >> $object->_process_command_stack(); >> } >> $self->clear_active_message(); >> >> >> George >> >> >> >> On 01/20/2014 07:42 PM, Kevin Robert Keegan wrote: >> >> Sorry, yes use the web interface built into the hub to change a device >> state. >> >> I figure some people would be interested in using the hub as a "Wife >> Acceptable Interface" while using MH as the more robust backend. >> >> Kevin >> >> >> On Mon, Jan 20, 2014 at 4:40 PM, George Clark <ge...@fe...>wrote: >> >>> Hi Kevin, >>> >>> I'm glad to test, but I'm not sure what you mean by use the hub to >>> control an object? >>> >>> You mean use the http connection to the 2540N to change a devices state >>> while mh is connected to the modem port? >>> >>> On 01/20/2014 07:36 PM, Kevin Robert Keegan wrote: >>> > Can you test one thing for me? I would like to know what happens when >>> > you use the hub to control an object. What does MH do if anything? >>> > Does it recognize the change? Does it implode when it receives an >>> > acknowledgement to a command that it never sent? I could inject some >>> > fake messages, but I figure it would be easier for you to test it out. >>> > >>> >>> >> >> > |
From: George C. <ge...@fe...> - 2014-02-04 02:30:53
|
Hi Kevin, I'll have to get back into mh again. The linking code made a real hash of my links and I had to go back to houselinc to get everything working again. I was also having reliability issues in the network, but I finally got houselinc to run diagnostics reliably. I have not tried the mh linking again now that the network seems more reliable. I still have no idea why it rewrote links at 100% brightness when I had specified 20% and 50% in places. I'll try it again tomorrow. I've been bouncing back and forth between mh and pytomation. mh has a more mature insteon / x10 implementation except for the lack of 2412N support. Though that's now working. Pytomation X10 was incomplete, which I added. But tonight I found some architecture challenges, because of X10 needing multi-part commands sent in sequence, pytomation gets stuck resending for a while. The other thing going for pytomation is built-in support for the arduino uno, and it seems to be lightweight enough to run reasonably well on the raspberry pi, although I've not tried mh there yet. The arduino seems perfect to monitor doors, windows, smoke, boiler trouble, water sump float switches, moisture sensors, etc. Thanks for the work on this. George On 02/03/2014 06:50 PM, Kevin Robert Keegan wrote: > George, > > Based on you success using the InsteonIP code, I brought it up-to-date > with the Master branch. I also added some code that should prevent MH > from crashing when the hub is used to control any insteon objects. If > you have a chance test out the code and let me know if it works: > > https://github.com/krkeegan/misterhouse/tree/InsteonIP > > If it seems to go alright, we can merge it into Master. > > Kevin > > > On Mon, Jan 20, 2014 at 5:14 PM, Kevin Robert Keegan > <ke...@kr... <mailto:ke...@kr...>> wrote: > > Awesome, thanks for doing that. > > We never coded MH with this in mind, so it isn't really all that > surprising. Just curious to see what would happen. > > I can easily patch that issue, but I suspect there are many more. > > > On Mon, Jan 20, 2014 at 4:58 PM, George Clark > <ge...@fe... <mailto:ge...@fe...>> wrote: > > Hi Kevin, > > Bad news ... Crashed > > Can't call method "setby" on an undefined value at > /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm > line 930. > at mh line 31. > main::__ANON__("Can't call method \"setby\" on an > undefined value at /home/gac/"...) called at > /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm > line 930 > Insteon_PLM::_parse_data(Insteon_PLM=HASH(0x9816fd8), > "025806025028f55c20d956611341") called at > /home/gac/automation/misterhouse/bin/../lib/Insteon_PLM.pm > line 264 > > Insteon_PLM::check_for_data(Insteon_PLM=HASH(0x9816fd8)) > called at > /home/gac/automation/misterhouse/bin/../lib/Insteon/BaseInterface.pm > line 33 > Insteon::BaseInterface::check_for_data() called at mh > line 1409 > main::run_hooks_("MainLoop_pre") called at (eval 87) > line 5 > main::MainLoop_pre_hooks() called at mh line 1522 > main::check_for_action called at mh line 3303 > main::monitor_commands called at mh line 6724 > > It took me a bit, I had never set up any scenes on the > 2540N, so I had to figure that out. Not particularly > intuitive, but done. As soon as I click on or off for the > scene using the web interface on the 2540N, mh dies. > > Line messages are not going line up for you due to the IP > changes, so here is the context: > > else > { > my $message_to_string = > ($self->active_message) ? $self->active_message->to_string() : ""; > &::print_log("[Insteon_PLM] Received all-link > cleanup success: $message_to_string") > if > $self->active_message->setby->debuglevel(1, 'insteon'); > if (ref $self->active_message && ref > $self->active_message->setby){ <======= Line 930 > my $object = $self->active_message->setby; > $object->is_acknowledged(1); > $object->_process_command_stack(); > } > $self->clear_active_message(); > > > George > > > > On 01/20/2014 07:42 PM, Kevin Robert Keegan wrote: >> Sorry, yes use the web interface built into the hub to change >> a device state. >> >> I figure some people would be interested in using the hub as >> a "Wife Acceptable Interface" while using MH as the more >> robust backend. >> >> Kevin >> >> >> On Mon, Jan 20, 2014 at 4:40 PM, George Clark >> <ge...@fe... <mailto:ge...@fe...>> wrote: >> >> Hi Kevin, >> >> I'm glad to test, but I'm not sure what you mean by use >> the hub to >> control an object? >> >> You mean use the http connection to the 2540N to change a >> devices state >> while mh is connected to the modem port? >> >> On 01/20/2014 07:36 PM, Kevin Robert Keegan wrote: >> > Can you test one thing for me? I would like to know >> what happens when >> > you use the hub to control an object. What does MH do >> if anything? >> > Does it recognize the change? Does it implode when it >> receives an >> > acknowledgement to a command that it never sent? I >> could inject some >> > fake messages, but I figure it would be easier for you >> to test it out. >> > >> >> > > > > > > ------------------------------------------------------------------------------ > Managing the Performance of Cloud-Based Applications > Take advantage of what the Cloud has to offer - Avoid Common Pitfalls. > Read the Whitepaper. > http://pubads.g.doubleclick.net/gampad/clk?id=121051231&iu=/4140/ostg.clktrk > > > ________________________________________________________ > To unsubscribe from this list, go to: https://lists.sourceforge.net/lists/listinfo/misterhouse-users > |
From: George C. <ge...@fe...> - 2014-02-04 17:16:21
|
(oops ... forgot to cc the list) Hi Kevin, I've checked out the krkeegan InsteonIP branch and got it all running again. Everything looks good, and I didn't see any crashes using the hub to send insteon commands. So that looks good too. Going forward, would you recommend my using krkeegan/master or hollie/master. Now that I look at the github network map, hollie seems way behind. Now for the important question, Is there some secret to defining links in the MHT so that they match up with my existing links? My network is all linked and running well, using houselink to manually link everything. I think I created the MHT definitions to try to match my existing links. But the AUDIT command report lots of missing links and orphan links. HouseLinc doesn't find any orphans. Is there some way to generate a "starter" MHT from the existing links? Or some recommended way to dump a link table so I can manually build a matching MHT? I only have a few things I need to keep working. Pre-set dim levels on some KPL buttons, and of course 3-way switches all tracking each other. I really don't want to run the syncing process again and end up breaking everything. George On 02/03/2014 06:50 PM, Kevin Robert Keegan wrote: > George, > > Based on you success using the InsteonIP code, I brought it up-to-date > with the Master branch. I also added some code that should prevent MH > from crashing when the hub is used to control any insteon objects. If > you have a chance test out the code and let me know if it works: > > https://github.com/krkeegan/misterhouse/tree/InsteonIP > > If it seems to go alright, we can merge it into Master. > > Kevin > |
From: Kevin R. K. <ke...@kr...> - 2014-02-04 17:30:43
|
George, Good to hear. No there is no difference between hollie/master and krkeegan/master. Some of my other branches have half done work for other features, they might appear to be ahead. I would generally say stick with hollie/master unless I need your help testing something. As for the links. There is no secret method. You want to use the following tools: - PLM->Scan all Changed Device Link Tables This will educate MH on the current state of the links on each device. You don't need to call this very often. -PLM->(AUDIT) Sync Links This will create report of the links that MH thinks are missing on your network, but won't change anything. -PLM->(AUDIT) Delete Orphans Similar to sync links, this will create a report of the links that MH thinks should be deleted from your devices. -Device->Log Links This will print a report of the links on the specific device. My recommendation, is to Scan first. Then run (Audit) Sync and focus on one device. If MH reports missing links, use Log Links for that device to see what the difference is. Do this for all devices. Then proceed to Audit Delete Links doing the same thing. Once you are satisfied, then run Sync Links and Delete Orphans. Kevin On Tue, Feb 4, 2014 at 9:14 AM, George Clark <ge...@fe...> wrote: > Hi Kevin, > > I've checked out the krkeegan InsteonIP branch and got it all running > again. Everything looks good, and I didn't see any crashes using the > hub to send insteon commands. So that looks good too. > > Going forward, would you recommend my using krkeegan/master or > hollie/master. Now that I look at the github network map, hollie seems > way behind. > > Now for the important question, Is there some secret to defining links > in the MHT so that they match up with my existing links? My network is > all linked and running well, using houselink to manually link everything. > > I think I created the MHT definitions to try to match my existing > links. But the AUDIT command report lots of missing links and orphan > links. HouseLinc doesn't find any orphans. > > Is there some way to generate a "starter" MHT from the existing > links? Or some recommended way to dump a link table so I can manually > build a matching MHT? I only have a few things I need to keep > working. Pre-set dim levels on some KPL buttons, and of course 3-way > switches all tracking each other. > > I really don't want to run the syncing process again and end up breaking > everything. > > George > > On 02/03/2014 06:50 PM, Kevin Robert Keegan wrote: > > George, > > > > Based on you success using the InsteonIP code, I brought it up-to-date > > with the Master branch. I also added some code that should prevent MH > > from crashing when the hub is used to control any insteon objects. If > > you have a chance test out the code and let me know if it works: > > > > https://github.com/krkeegan/misterhouse/tree/InsteonIP > > > > If it seems to go alright, we can merge it into Master. > > > > Kevin > > > > |
From: George C. <ge...@fe...> - 2014-02-04 20:26:37
|
Hi Kevin, Gradually syncing links. I'm seeing maybe a memory leak? The parsed data fragments have been growing and growing as I sync more devices. It doesn't seem to get cleared. 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: 5 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: 02541a 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: e20d95621160015022541ae20d956222be3502278ce130101c706001515155023af4720d9562129011515151515151515150223b90e0a2bd6060222922420d95621291f0222e95120d956212be8 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Prepending prior data fragment: 502541ae20d95621160015022541ae20d956222be3502278ce130101c706001515155023af4720d9562129011515151515151515150223b90e0a2bd6060222922420d95621291f0222e95120d956212be8 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Received PLM raw data: 502541ae20d95621160015022541ae20d956222be3502278ce130101c706001515155023af4720d9562129011515151515151515150223b90e0a2bd6060222922420d95621291f0222e95120d956212be8025022e95120d956212200 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: 5 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: 02541a 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: e20d95621160015022541ae20d956222be3502278ce130101c706001515155023af4720d9562129011515151515151515150223b90e0a2bd6060222922420d95621291f0222e95120d956212be8 04/02/2014 15:24:32 [Insteon_PLM] DEBUG4: |
From: Kevin R. K. <ke...@kr...> - 2014-02-04 21:08:39
|
Hmm, that is very odd. So PLM commands start with 02, so I split the long chain of commands at every 02, which gave me: 5 02541ae20d95621160015 022541ae20d956222be35 02278ce130101c706001515155 023af4720d956212901151515151515151515 0223b90e0a2bd606 0222922420d95621291f 0222e95120d956212be8 025022e95120d956212200 Now the known PLM commands range from 0250-0273. The vast majority of these appear to be junk as they are all less than 0250. The second line starts with 0254 which is an odd, generally unused command in the PLM signifying a button press, but the following 1A byte in that message is unknown to us. Similarly, the final message listed starts with 0250 and otherwise appears to be a valid message in terms of length. But the Command 1 location, the second to last byte, is 22. A command 1 of 22 is again, not something we generally see. This suggests that something very odd is going on. I can also see a few patterns forming. If I had to guess, 20d956 is the address of your Hub? And, 22e951, is the address of a device on your network? I see those two addresses scattered throughout. I also see a long string of 1515.... which may be caused by the Hub saying "whoa, way to much data at once, slow down." My guess is that someone bytes are being lost. Given what I see, I would suspect that the bytes are being lost in the socket connection between the hub and MH. Why I am not sure. On Tue, Feb 4, 2014 at 12:26 PM, George Clark <ge...@fe...> wrote: > Hi Kevin, > > Gradually syncing links. I'm seeing maybe a memory leak? The parsed > data fragments have been growing and growing as I sync more devices. It > doesn't seem to get cleared. > > 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: 5 > 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: > 02541a > 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: > > e20d95621160015022541ae20d956222be3502278ce130101c706001515155023af4720d9562129011515151515151515150223b90e0a2bd6060222922420d95621291f0222e95120d956212be8 > 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Prepending prior data > fragment: > > 502541ae20d95621160015022541ae20d956222be3502278ce130101c706001515155023af4720d9562129011515151515151515150223b90e0a2bd6060222922420d95621291f0222e95120d956212be8 > 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Received PLM raw data: > > 502541ae20d95621160015022541ae20d956222be3502278ce130101c706001515155023af4720d9562129011515151515151515150223b90e0a2bd6060222922420d95621291f0222e95120d956212be8025022e95120d956212200 > 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: 5 > 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: > 02541a > 04/02/2014 15:24:32 [Insteon_PLM] DEBUG3: Saving parsed data fragment: > > e20d95621160015022541ae20d956222be3502278ce130101c706001515155023af4720d9562129011515151515151515150223b90e0a2bd6060222922420d95621291f0222e95120d956212be8 > 04/02/2014 15:24:32 [Insteon_PLM] DEBUG4: > > > |
From: George C. <ge...@fe...> - 2014-02-04 21:20:20
|
On 02/04/2014 04:08 PM, Kevin Robert Keegan wrote: > I can also see a few patterns forming. If I had to guess, 20d956 is > the address of your Hub? Yes > And, 22e951, is the address of a device on your network? Yes, #Kitchen Window 22.E9.51 P2477D R7.1 1013 (Load) I've not had any issues with communicating with that one. > I see those two addresses scattered throughout. I also see a long > string of 1515.... which may be caused by the Hub saying "whoa, way to > much data at once, slow down." Yes during sync operations I see messages pop up about PLM being "extremely busy" off and on. > > My guess is that someone bytes are being lost. Given what I see, I > would suspect that the bytes are being lost in the socket connection > between the hub and MH. Why I am not sure. > It's hard to believe that it's the TCP connection. That should be extremely reliable, as TCP will recover any lost or corrupted packets, assuming it's implemented correctly. George |
From: Kevin R. K. <ke...@kr...> - 2014-02-04 21:31:58
|
On Tue, Feb 4, 2014 at 1:20 PM, George Clark <ge...@fe...> wrote: > > I see those two addresses scattered throughout. I also see a long > > string of 1515.... which may be caused by the Hub saying "whoa, way to > > much data at once, slow down." > > Yes during sync operations I see messages pop up about PLM being > "extremely busy" off and on. > > > > My guess is that someone bytes are being lost. Given what I see, I > > would suspect that the bytes are being lost in the socket connection > > between the hub and MH. Why I am not sure. > > > It's hard to believe that it's the TCP connection. That should be > extremely reliable, as TCP will recover any lost or corrupted packets, > assuming it's implemented correctly. Agree, it would be strange. But I don't really have any other explanation as to why the Hub would be sending that many erroneous messages. Since you are seeing a lot of "extremely busy" messages, we should try and slow down how fast we talk to the Hub. It could be that we are overloading it causing it to drop bytes somehow. Do you still have Insteon_PLM_xmit_delay set to 1? Can you try and increase this to see if the "extremely busy" messages go away? |
From: George C. <ge...@fe...> - 2014-02-04 21:39:16
|
On 02/04/2014 04:31 PM, Kevin Robert Keegan wrote: > Do you still have Insteon_PLM_xmit_delay set to 1? Can you try and > increase this to see if the "extremely busy" messages go away? Yes. It's still at 1. I can bump it to 2, though now that everything is in sync, I'm not sure I can generate as much traffic. George |
From: George C. <ge...@fe...> - 2014-02-04 21:04:13
|
Hi Kevin, Okay. ... completed, with one "problem device" remaining. I cannot get my front porch light to sync up completely: AUDIT sync all links from the PLM shows one issue: 04/02/2014 15:51:27 [Sync all links] Now syncing: $l_front_porch (18 of 34) 04/02/2014 15:51:27 [Insteon::BaseController] (AUDIT) Adding responder record to $PLM from $l_front_porch cmd = add; data3 = 00; group = 01; is_controller = 0; ... 04/02/2014 15:51:27 [Sync all links] All links have completed syncing 04/02/2014 15:51:27 [Sync all links] WARN! Failures occured, some links involving the following objects remain out-of-sync: $l_front_porch, $l_back_hall_bH, $night_mode, These three are probably listed as failures because they all are linked together: night_mode (scene), keypad button H, and front porch light But when I try to sync the links, it fails: 04/02/2014 15:51:44 Running: l front porch sync links 04/02/2014 15:51:44 [Insteon::BaseController] Adding responder record to $PLM from $l_front_porch cmd = add; data3 = 00; group = 01; is_controller = 0; 04/02/2014 15:51:44 [Insteon::ALDB_PLM] WARN: attempt to add link to PLM that already exists! deviceid=28f55c, group=01, is_controller=0, subaddress=00 04/02/2014 15:51:44 $l_front_porch completed sync links This is the front porch link table: 04/02/2014 15:52:11 Running: l front porch log links 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] Link table for $l_front_porch health: good 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0fd7] is empty 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0fdf] is empty 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0fe7] rspndr(01) record to $l_back_hall_bA (08): onlevel=20% and ramp=0.1s (d3:00) 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0fef] rspndr(01) record to $PLM (a5): onlevel=20% and ramp=0.1s (d3:00) 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0ff7] contlr(01) record to $PLM, (d1:03, d2:00, d3:01) 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0fff] rspndr(01) record to $PLM (00): onlevel=100% and ramp=0.1s (d3:01) And here is the PLM link table (excerpt) for the links that mention front_porch 04/02/2014 15:52:29 Running: PLM log links 04/02/2014 15:52:29 [Insteon::ALDB_PLM] Link table health: good ... 04/02/2014 15:52:29 [Insteon::ALDB_PLM] cntlr(01) record to $l_front_porch (d1=01, d2=20, d3=41) 04/02/2014 15:52:29 [Insteon::ALDB_PLM] responder record to $l_front_porch(01) (d1=07, d2=00, d3=41) 04/02/2014 15:52:29 [Insteon::ALDB_PLM] cntlr(01) record to $l_front_porch (d1=01, d2=20, d3=41) 04/02/2014 15:52:29 [Insteon::ALDB_PLM] cntlr($night_mode (a5)) record to $l_front_porch (d1=01, d2=00, d3=a5) Any suggestions on how to get beyond this one? It seems to be a stuck link on the PLM. mh won't delete it, and can't add it. Thanks, George On 02/04/2014 12:30 PM, Kevin Robert Keegan wrote: > My recommendation, is to Scan first. Then run (Audit) Sync and focus > on one device. If MH reports missing links, use Log Links for that > device to see what the difference is. Do this for all devices. Then > proceed to Audit Delete Links doing the same thing. Once you are > satisfied, then run Sync Links and Delete Orphans. > > Kevin |
From: Kevin R. K. <ke...@kr...> - 2014-02-04 21:15:44
|
I can't see the message in the snippit you provided, but it looks MH is reporting a problem with (Audit) Sync Links because MH was not able to successfully scan the link tables of the following devices: $l_front_porch, $l_back_hall_bH, $night_mode, That last one looks like a scene, which may be out of sync simply because it is a scene controlling one or both of the prior two objects. So, run the "Log Links" voice command on each physical device listed above. It will print out a message in the print log. I suspect it will say they are out-of-sync. If you see that message you should run "Scan Link Table" on that specific device. If the scan completes successfully, MH will have an accurate understanding of the state of these devices and you will be able to run (AUDIT) Sync links successfully. On Tue, Feb 4, 2014 at 1:04 PM, George Clark <ge...@fe...> wrote: > Hi Kevin, > > Okay. ... completed, with one "problem device" remaining. I cannot > get my front porch light to sync up completely: > > AUDIT sync all links from the PLM shows one issue: > > 04/02/2014 15:51:27 [Sync all links] Now syncing: $l_front_porch (18 of > 34) > 04/02/2014 15:51:27 [Insteon::BaseController] (AUDIT) Adding responder > record to $PLM from $l_front_porch > cmd = add; data3 = 00; group = 01; is_controller = 0; > ... > 04/02/2014 15:51:27 [Sync all links] All links have completed syncing > 04/02/2014 15:51:27 [Sync all links] WARN! Failures occured, some links > involving the following objects remain out-of-sync: $l_front_porch, > $l_back_hall_bH, $night_mode, > > > These three are probably listed as failures because they all are linked > together: night_mode (scene), keypad button H, and front porch light > > But when I try to sync the links, it fails: > > 04/02/2014 15:51:44 Running: l front porch sync links > 04/02/2014 15:51:44 [Insteon::BaseController] Adding responder record > to $PLM from $l_front_porch > cmd = add; data3 = 00; group = 01; is_controller = 0; > 04/02/2014 15:51:44 [Insteon::ALDB_PLM] WARN: attempt to add link to > PLM that already exists! deviceid=28f55c, group=01, is_controller=0, > subaddress=00 > 04/02/2014 15:51:44 $l_front_porch completed sync links > > This is the front porch link table: > > 04/02/2014 15:52:11 Running: l front porch log links > 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] Link table for > $l_front_porch health: good > 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0fd7] is empty > 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0fdf] is empty > 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0fe7] rspndr(01) > record to $l_back_hall_bA (08): onlevel=20% and ramp=0.1s (d3:00) > 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0fef] rspndr(01) > record to $PLM (a5): onlevel=20% and ramp=0.1s (d3:00) > 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0ff7] contlr(01) > record to $PLM, (d1:03, d2:00, d3:01) > 04/02/2014 15:52:11 [Insteon::AllLinkDatabase] [0x0fff] rspndr(01) > record to $PLM (00): onlevel=100% and ramp=0.1s (d3:01) > > And here is the PLM link table (excerpt) for the links that mention > front_porch > > 04/02/2014 15:52:29 Running: PLM log links > 04/02/2014 15:52:29 [Insteon::ALDB_PLM] Link table health: good > ... > 04/02/2014 15:52:29 [Insteon::ALDB_PLM] cntlr(01) record to > $l_front_porch (d1=01, d2=20, d3=41) > 04/02/2014 15:52:29 [Insteon::ALDB_PLM] responder record to > $l_front_porch(01) (d1=07, d2=00, d3=41) > 04/02/2014 15:52:29 [Insteon::ALDB_PLM] cntlr(01) record to > $l_front_porch (d1=01, d2=20, d3=41) > 04/02/2014 15:52:29 [Insteon::ALDB_PLM] cntlr($night_mode (a5)) record > to $l_front_porch (d1=01, d2=00, d3=a5) > > Any suggestions on how to get beyond this one? It seems to be a stuck > link on the PLM. mh won't delete it, and can't add it. > > Thanks, > George > > On 02/04/2014 12:30 PM, Kevin Robert Keegan wrote: > > My recommendation, is to Scan first. Then run (Audit) Sync and focus > > on one device. If MH reports missing links, use Log Links for that > > device to see what the difference is. Do this for all devices. Then > > proceed to Audit Delete Links doing the same thing. Once you are > > satisfied, then run Sync Links and Delete Orphans. > > > > Kevin > > |
From: George C. <ge...@fe...> - 2014-02-04 21:37:01
|
Hi Kevin, I hate flooding the list with big messages, but here is a more complete status: Nothing is reporting out-of-sync that I can find. but the attempt to sync links still fails. Here in order are: -Definitions - Log links for the three physical devices - Audit - fails - Sync - fails Here are the mht definitions: INSTEON_SWITCHLINC, 28.F5.5C, l_front_porch, All_Lights|Outside #Front porch 28.F5.5C 2477D R7.2 3913 (Load) INSTEON_KEYPADLINC, 22.92.24:08, l_back_hall_bH, hidden #Hall Button H: Night scene # Scene for night mode # name, device, cont, resp, on_lev, ramp_rate INSTEON_ICONTROLLER, A5, night_mode SCENE_BUILD, night_mode, l_back_porch, 0, 1, 20%, 0s SCENE_BUILD, night_mode, l_kitchen_window, 0, 1, 20%, 0s SCENE_BUILD, night_mode, l_front_porch, 0, 1, 20%, 0s SCENE_BUILD, night_mode, l_back_hall_bH, 1, 0, 20%, 0s The actual linking works correctly. Button H will toggle the 3 devices between off, and 20%. Just confirmed that it still works. Both devices are in-sync with healthy link tables: Here are the Log Links: 04/02/2014 16:17:12 Running: l front porch log links 04/02/2014 16:17:12 [Insteon::AllLinkDatabase] Link table for $l_front_porch health: good 04/02/2014 16:17:12 [Insteon::AllLinkDatabase] [0x0fd7] is empty 04/02/2014 16:17:12 [Insteon::AllLinkDatabase] [0x0fdf] is empty 04/02/2014 16:17:12 [Insteon::AllLinkDatabase] [0x0fe7] rspndr(01) record to $l_back_hall_bA (08): onlevel=20% and ramp=0.1s (d3:00) 04/02/2014 16:17:12 [Insteon::AllLinkDatabase] [0x0fef] rspndr(01) record to $PLM (a5): onlevel=20% and ramp=0.1s (d3:00) 04/02/2014 16:17:12 [Insteon::AllLinkDatabase] [0x0ff7] contlr(01) record to $PLM, (d1:03, d2:00, d3:01) 04/02/2014 16:17:12 [Insteon::AllLinkDatabase] [0x0fff] rspndr(01) record to $PLM (00): onlevel=100% and ramp=0.1s (d3:01) 04/02/2014 16:17:31 Running: l back hall bA log links 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] Link table for $l_back_hall_bA health: good 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0FF8] contlr(01) record to $PLM, (d1:03, d2:00, d3:01) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0f68] rspndr(02) record to $l_kitchen_recess (01): onlevel=on and ramp=none (d3:02) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0f70] rspndr(01) record to $PLM (a4): onlevel=100% and ramp=0.1s (d3:01) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0f78] rspndr(01) record to $l_back_entrance (01): onlevel=100% and ramp=0.1s (d3:01) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0f80] rspndr(01) record to $l_back_top_stairs (01): onlevel=100% and ramp=0.1s (d3:01) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0f88] rspndr(04) record to $l_basement (01): onlevel=on and ramp=none (d3:04) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0f90] rspndr(03) record to $l_back_room (01): onlevel=on and ramp=none (d3:03) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0f98] contlr(08) record to $l_front_porch, (d1:03, d2:00, d3:08) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0fa0] contlr(08) record to $l_kitchen_window, (d1:03, d2:00, d3:08) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0fa8] contlr(08) record to $l_back_porch, (d1:03, d2:00, d3:08) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0fb0] contlr(08) record to $PLM, (d1:03, d2:00, d3:08) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0fb8] contlr(04) record to $l_basement, (d1:03, d2:00, d3:04) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0fc0] contlr(04) record to $PLM, (d1:03, d2:00, d3:04) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0fc8] contlr(03) record to $l_back_room, (d1:03, d2:00, d3:03) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0fd0] contlr(03) record to $PLM, (d1:03, d2:00, d3:03) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0fd8] contlr(02) record to $l_kitchen_recess, (d1:03, d2:00, d3:02) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0fe0] contlr(02) record to $PLM, (d1:03, d2:00, d3:02) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0fe8] contlr(01) record to $l_back_top_stairs, (d1:03, d2:00, d3:01) 04/02/2014 16:17:31 [Insteon::AllLinkDatabase] [0x0ff0] contlr(01) record to $l_back_entrance, (d1:03, d2:00, d3:01) But the audit still finds errors 04/02/2014 16:18:46 Running: PLM AUDIT - sync all links 04/02/2014 16:18:46 [Sync all links] Starting now! ... 04/02/2014 16:18:46 [Sync all links] Now syncing: $io_driveway_camera (1 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $io_driveway_camera 04/02/2014 16:18:46 [Sync all links] Now syncing: $io_back_door (2 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $io_back_door 04/02/2014 16:18:46 [Sync all links] Now syncing: $io_garage_door (3 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $io_garage_door 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_back_top_stairs (4 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_back_top_stairs 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_under_counter (5 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_under_counter 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_back_porch (6 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_back_porch 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_basement (7 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_basement 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_bath_fan_lt (8 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_bath_fan_lt 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_bath_vanity (9 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_bath_vanity 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_kitchen_window (10 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_kitchen_window 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_kitchen_oh_m (11 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_kitchen_oh_m 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_back_room (12 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_back_room 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_back_entrance (13 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_back_entrance 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_2fl_hall_m (14 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_2fl_hall_m 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_2fl_hall_s1 (15 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_2fl_hall_s1 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_2fl_hall_s2 (16 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_2fl_hall_s2 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_garage (17 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_garage *04/02/2014 16:18:46 [Sync all links] Now syncing: $l_front_porch (18 of 34)** **04/02/2014 16:18:46 [Insteon::BaseController] (AUDIT) Adding responder record to $PLM from $l_front_porch** **cmd = add; data3 = 00; group = 01; is_controller = 0; ** *04/02/2014 16:18:46 [Sync all links] Now syncing: $l_kitchen_recess (19 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_kitchen_recess 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_kitchen_u_hi (20 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_kitchen_u_hi 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_kitchen_u_low (21 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_kitchen_u_low 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_kitchen_oh_s2 (22 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_kitchen_oh_s2 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_kitchen_oh_s1 (23 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_kitchen_oh_s1 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_dining_room (24 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_dining_room 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_back_hall_bA (25 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_back_hall_bA 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_back_hall_bB (26 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_back_hall_bB 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_back_hall_bC (27 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_back_hall_bC 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_back_hall_bD (28 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_back_hall_bD 04/02/2014 16:18:46 [Sync all links] Now syncing: $l_back_hall_bH (29 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $l_back_hall_bH 04/02/2014 16:18:46 [Sync all links] Now syncing: $front_hall (30 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $front_hall 04/02/2014 16:18:46 [Sync all links] Now syncing: $kitchen_overhead (31 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $kitchen_overhead 04/02/2014 16:18:46 [Sync all links] Now syncing: $kitchen_counter (32 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $kitchen_counter 04/02/2014 16:18:46 [Sync all links] Now syncing: $back_hall (33 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $back_hall 04/02/2014 16:18:46 [Sync all links] Now syncing: $night_mode (34 of 34) 04/02/2014 16:18:46 [Insteon::BaseController] Nothing to do when syncing links for $night_mode 04/02/2014 16:18:46 [Sync all links] All links have completed syncing 04/02/2014 16:18:46 [Sync all links] WARN! Failures occured, some links involving the following objects remain out-of-sync: $l_front_porch, $l_back_hall_bH, $night_mode, And the log links from the PLM 04/02/2014 16:18:26 Running: PLM log links 04/02/2014 16:18:26 [Insteon::ALDB_PLM] Link table health: good 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_back_top_stairs (d1=01, d2=1f, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_back_top_stairs(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($back_hall (a4)) record to $l_back_top_stairs (d1=01, d2=00, d3=a4) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_under_counter (d1=01, d2=32, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_under_counter(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($kitchen_counter (a3)) record to $l_under_counter (d1=01, d2=00, d3=a3) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_back_porch (d1=01, d2=1f, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_back_porch(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($night_mode (a5)) record to $l_back_porch (d1=01, d2=00, d3=a5) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $io_driveway_camera (d1=07, d2=00, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $io_driveway_camera(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $io_back_door (d1=07, d2=00, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $io_back_door(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $io_back_door (d1=07, d2=00, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $io_garage_door (d1=07, d2=00, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $io_garage_door(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_kitchen_recess (d1=01, d2=1c, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_kitchen_recess(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_kitchen_u_hi(03) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_kitchen_u_low(04) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_kitchen_oh_s2(06) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($kitchen_overhead (a2)) record to $l_kitchen_recess (d1=01, d2=00, d3=a2) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_back_hall_bA (d1=02, d2=2c, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_back_hall_bA(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_back_hall_bA (d1=02, d2=2c, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_back_hall_bB(02) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_back_hall_bC(03) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_back_hall_bD(04) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_back_hall_bH(08) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($back_hall (a4)) record to $l_back_hall_bA (d1=01, d2=00, d3=a4) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_basement (d1=02, d2=2a, d3=42) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_basement(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_bath_fan_lt (d1=02, d2=2a, d3=42) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_bath_fan_lt(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_kitchen_window (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_kitchen_window(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_kitchen_window (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($night_mode (a5)) record to $l_kitchen_window (d1=01, d2=00, d3=a5) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_kitchen_oh_m (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_kitchen_oh_m(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_kitchen_oh_m (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($kitchen_overhead (a2)) record to $l_kitchen_oh_m (d1=01, d2=00, d3=a2) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_back_room (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_back_room(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_bath_vanity (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_bath_vanity(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_kitchen_oh_s1 (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_kitchen_oh_s1(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($kitchen_overhead (a2)) record to $l_kitchen_oh_s1 (d1=01, d2=00, d3=a2) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_back_entrance (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_back_entrance(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($back_hall (a4)) record to $l_back_entrance (d1=01, d2=00, d3=a4) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_2fl_hall_s2 (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_2fl_hall_s2(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($front_hall (a1)) record to $l_2fl_hall_s2 (d1=01, d2=00, d3=a1) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_2fl_hall_m (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_2fl_hall_m(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($front_hall (a1)) record to $l_2fl_hall_m (d1=01, d2=00, d3=a1) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_garage (d1=02, d2=2a, d3=43) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_garage(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_dining_room (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_dining_room(01) (d1=00, d2=00, d3=00) *04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_front_porch (d1=01, d2=20, d3=41)** **04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_front_porch(01) (d1=07, d2=00, d3=41)** **04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_front_porch (d1=01, d2=20, d3=41)** **04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($night_mode (a5)) record to $l_front_porch (d1=01, d2=00, d3=a5)** *04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr(01) record to $l_2fl_hall_s1 (d1=01, d2=20, d3=41) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] responder record to $l_2fl_hall_s1(01) (d1=00, d2=00, d3=00) 04/02/2014 16:18:26 [Insteon::ALDB_PLM] cntlr($front_hall (a1)) record to $l_2fl_hall_s1 (d1=01, d2=00, d3=a1) Finally, trying to fix it: Fails. 04/02/2014 16:32:52 Running: l front porch sync links 04/02/2014 16:32:52 [Insteon::BaseController] Adding responder record to $PLM from $l_front_porch cmd = add; data3 = 00; group = 01; is_controller = 0; 04/02/2014 16:32:52 [Insteon::ALDB_PLM] WARN: attempt to add link to PLM that already exists! deviceid=28f55c, group=01, is_controller=0, subaddress=00 04/02/2014 16:32:52 $l_front_porch completed sync links 04/02/2014 16:33:00 : Saving object states ... done On 02/04/2014 04:15 PM, Kevin Robert Keegan wrote: > I can't see the message in the snippit you provided, but it looks MH > is reporting a problem with (Audit) Sync Links because MH was not able > to successfully scan the link tables of the following devices: > > $l_front_porch, > $l_back_hall_bH, > $night_mode, > > That last one looks like a scene, which may be out of sync simply > because it is a scene controlling one or both of the prior two objects. > > So, run the "Log Links" voice command on each physical device listed > above. It will print out a message in the print log. I suspect it > will say they are out-of-sync. If you see that message you should run > "Scan Link Table" on that specific device. > > If the scan completes successfully, MH will have an accurate > understanding of the state of these devices and you will be able to > run (AUDIT) Sync links successfully. > |
From: Kevin R. K. <ke...@kr...> - 2014-02-04 22:13:37
|
On Tue, Feb 4, 2014 at 1:36 PM, George Clark <ge...@fe...> wrote: > Finally, trying to fix it: Fails. > > 04/02/2014 16:32:52 Running: l front porch sync links > 04/02/2014 16:32:52 [Insteon::BaseController] Adding responder record to > $PLM from $l_front_porch > > cmd = add; data3 = 00; group = 01; is_controller = 0; > 04/02/2014 16:32:52 [Insteon::ALDB_PLM] WARN: attempt to add link to PLM > that already exists! deviceid=28f55c, group=01, is_controller=0, > subaddress=00 > 04/02/2014 16:32:52 $l_front_porch completed sync links > 04/02/2014 16:33:00 : Saving object states ... done > I think I know where this bug is arising from. I will push a patch later today. Not sure about the $l_back_hall_bH and $night_mode issues yet. But let's tackle one issue at a time and maybe it will fix the other issues. |
From: Kevin R. K. <ke...@kr...> - 2014-02-04 22:58:22
|
On Tue, Feb 4, 2014 at 1:36 PM, George Clark <ge...@fe...> wrote: > 04/02/2014 16:18:46 Running: PLM AUDIT - sync all links > 04/02/2014 16:18:46 [Sync all links] Starting now! > ... > 04/02/2014 16:18:46 [Sync all links] Now syncing: $io_driveway_camera (1 > of 34) > George, what printed to the log for those ellipsis? |
From: Kevin R. K. <ke...@kr...> - 2014-02-05 05:46:23
|
George, I updated my branch InsteonIP which should fix the issues you have identified. Kevin On Tue, Feb 4, 2014 at 3:04 PM, Kevin Robert Keegan <ke...@kr...>wrote: > You were right, it isn't. This still seems very strange to me. > > > On Tue, Feb 4, 2014 at 3:02 PM, George Clark <ge...@fe...> wrote: > >> Just the adding of 34 devices to the list to check. >> >> Sorry, I didn't think it would be of any interest. >> >> 04/02/2014 11:59:37 [Sync all links] Adding $io_driveway_camera to sync >> queue >> 04/02/2014 11:59:37 [Sync all links] Adding $io_back_door to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $io_garage_door to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_back_top_stairs to sync >> queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_under_counter to sync >> queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_back_porch to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_basement to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_bath_fan_lt to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_bath_vanity to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_kitchen_window to sync >> queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_kitchen_oh_m to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_back_room to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_back_entrance to sync >> queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_2fl_hall_m to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_2fl_hall_s1 to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_2fl_hall_s2 to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_garage to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_front_porch to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_kitchen_recess to sync >> queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_kitchen_u_hi to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_kitchen_u_low to sync >> queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_kitchen_oh_s2 to sync >> queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_kitchen_oh_s1 to sync >> queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_dining_room to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_back_hall_bA to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_back_hall_bB to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_back_hall_bC to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_back_hall_bD to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $l_back_hall_bH to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $front_hall to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $kitchen_overhead to sync >> queue >> 04/02/2014 11:59:37 [Sync all links] Adding $kitchen_counter to sync >> queue >> 04/02/2014 11:59:37 [Sync all links] Adding $back_hall to sync queue >> 04/02/2014 11:59:37 [Sync all links] Adding $night_mode to sync queue >> >> >> >> On 02/04/2014 05:58 PM, Kevin Robert Keegan wrote: >> >> On Tue, Feb 4, 2014 at 1:36 PM, George Clark <ge...@fe...>wrote: >> >>> 04/02/2014 16:18:46 Running: PLM AUDIT - sync all links >>> 04/02/2014 16:18:46 [Sync all links] Starting now! >>> ... >>> 04/02/2014 16:18:46 [Sync all links] Now syncing: $io_driveway_camera >>> (1 of 34) >>> >> >> George, what printed to the log for those ellipsis? >> >> >> > |
From: George C. <ge...@fe...> - 2014-02-05 14:06:12
|
Hi Kevin, After your changes, mh found the duplicate link and was happy. The linking is now clean. Thanks again for your help on this. It's working well. George On 02/05/2014 12:46 AM, Kevin Robert Keegan wrote: > George, > > I updated my branch InsteonIP which should fix the issues you have > identified. > > Kevin > > > On Tue, Feb 4, 2014 at 3:04 PM, Kevin Robert Keegan > <ke...@kr... <mailto:ke...@kr...>> wrote: > > You were right, it isn't. This still seems very strange to me. > > > On Tue, Feb 4, 2014 at 3:02 PM, George Clark <ge...@fe... > <mailto:ge...@fe...>> wrote: > > Just the adding of 34 devices to the list to check. > > Sorry, I didn't think it would be of any interest. > > 04/02/2014 11:59:37 [Sync all links] Adding > $io_driveway_camera to sync queue > 04/02/2014 11:59:37 [Sync all links] Adding $io_back_door to > sync queue > |
From: Eloy P. <pe...@ch...> - 2014-02-04 17:49:57
|
On 02/04/2014 12:30 PM, Kevin Robert Keegan wrote: > George, > > Good to hear. > > No there is no difference between hollie/master and krkeegan/master. > Some of my other branches have half done work for other features, they > might appear to be ahead. I would generally say stick with > hollie/master unless I need your help testing something. > > As for the links. There is no secret method. You want to use the > following tools: > - PLM->Scan all Changed Device Link Tables > This will educate MH on the current state of the links on each device. > You don't need to call this very often. I've always been a bit confused about when exactly one needs to scan links... The .mht file defines the relationships between devices, and then MH verifies that the devices themselves have these same relationships after scanning the links in the devices, right? If so, my takeaway is that, assuming that all links in the devices are good, and in sync with what MH thinks, then one only needs to scan links when doing link manipulation or adding new devices. But just restarting MH does not require a re-scan. Is this correct? Cheers, Eloy Paris.- |
From: Kevin R. K. <ke...@kr...> - 2014-02-04 18:15:10
|
On Tue, Feb 4, 2014 at 9:49 AM, Eloy Paris <pe...@ch...> wrote: > I've always been a bit confused about when exactly one needs to scan > links... Yes, it is becoming more apparent to me that the nomenclature used in MH is confusing and misleading. Add that to the list of things to fix. > The .mht file defines the relationships between devices, and > then MH verifies that the devices themselves have these same > relationships after scanning the links in the devices, right? If so, my > takeaway is that, assuming that all links in the devices are good, and > in sync with what MH thinks, then one only needs to scan links when > doing link manipulation or adding new devices. But just restarting MH > does not require a re-scan. Is this correct? > Yes. "Scan Links" simply causes MH to query each device for the state of the links on the device. MH caches this link database and saves it through reboots. When running Sync/Delete Links, MH compares the links defined in the mht file to this cached database. In general, you only need to run "Scan Links" when installing a new device, when manual changes have been performed on a device, when factory resetting a device, or when power has been lost to a device. Any changes to the device's link table made by MH are added to the cached version of the database inside MH and do not require a scan. You can also almost always run "Scan CHANGED Device Link Tables." Each device has a link table version number that changes whenever a change is made to a device. When using this command, MH will scan the PLM (it lacks a version number) and then only scan those devices which report version numbers which are different. This should be significantly faster. |