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 <geomh@fenachrone.com> 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