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 >> >> > > |