X10 resends die with Can't call method "get_object_name" on an undefined value

[marcmerlin]

Mmmh, I had just done a scan all links, I wonder how those got lost, so I redid a new scan all links
and the first failed:

22/03/2013 22:44:06 [Scan all link tables] Now scanning: $entryway (12 of 27)
22/03/2013 22:44:06 [Insteon::ALDB_i2] $entryway reading ALDB at location: 0x0000
(...)
22/03/2013 22:44:08 [Insteon::BaseInterface] DEBUG2: Message received with 1 hops left, delaying next transmit to avoid collisions with remaining hops.
22/03/2013 22:44:08 [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:read_write_aldb; type:direct; group:
22/03/2013 22:44:08 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $entryway
22/03/2013 22:44:08 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0ff7] received: 00 for _mem_activity=scan _mem_action=aldb_i2read
22/03/2013 22:44:08 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0ff7] received ack
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM raw data: 02510f230218d4ce112f0001010ff701a2040e0912ff000000
22/03/2013 22:44:08 [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:read_write_aldb; type:direct; group:
22/03/2013 22:44:08 [Insteon::BaseInterface] Processing message for $entryway
22/03/2013 22:44:08 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $entryway
22/03/2013 22:44:08 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0ff7] received: 0001010ff701a2040e0912ff000000 for _mem_activity=scan mem_action=aldb_i2readack
22/03/2013 22:44:08 [Insteon::ALDB_i2] $entryway reading ALDB at location: 0x0fef
22/03/2013 22:44:08 [Insteon_PLM] DEBUG2: Sending ce00 incurred delay of 0.61 seconds; starting hop-count: ? > > 22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Sending PLM raw data: 0263ce00 > > 22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM raw data: 0263ce0006
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM acknowledge: ce00 > > 22/03/2013 22:44:09 [Insteon_PLM] DEBUG2: Sending c380 incurred delay of 1.15 seconds; starting hop-count: ? > > 22/03/2013 22:44:09 [Insteon_PLM] DEBUG3: Sending PLM raw data: 0263c380
22/03/2013 22:44:09 [Insteon_PLM] DEBUG3: Received PLM raw data: 15 > > 22/03/2013 22:44:09 [Insteon_PLM] DEBUG3: Interface extremely busy. Resending command after delaying for 1 second > > 22/03/2013 22:44:10 [Insteon::BaseMessage] WARN: now resending c380 after 1 attempts.
Can't call method "get_object_name" on an undefined value at ../lib/Insteon/Message.pm line 139. > > at ./mh line 31
main::ANON('Can't call method "get_object_name" on an undefined value at...') called at ../lib/Insteon/Message.pm line 139
Insteon::BaseMessage::send('Insteon::X10Message=HASH(0xbc87618)', 'Insteon_PLM=HASH(0xad80074)') called at ../lib/Insteon/BaseInterface.pm line 235
Insteon::BaseInterface::process_queue('Insteon_PLM=HASH(0xad80074)') called at ../lib/Insteon_PLM.pm line 189 > > Insteon_PLM::check_for_data('Insteon_PLM=HASH(0xad80074)') called at ../lib/Insteon/BaseInterface.pm line 11
Insteon::BaseInterface::check_for_data() called at ./mh line 1402
main::run_hooks('MainLoop_pre') called at (eval 335) line 5 > > main::MainLoop_pre_hooks() called at ./mh line 1515 > > main::check_for_action called at ./mh line 3296 > > main::monitor_commands called at ./mh line 6713

[mstovenour]

These logs may be missing something important. I see that the stack trace was for:
Insteon::BaseMessage::send('Insteon::X10Message=HASH(0xbc87618)', 'Insteon_PLM=HASH(0xad80074)') called at ../lib/Insteon/BaseInterface.pm line 235

[marcmerlin]

It's not easy to paste the logs here, especially because after the fact logs in print.log do not also contain stderr output.
That said, here's all the output from my logs just before the crash at 22:40:10 which is already pasted above:
22/03/2013 22:44:06 [Scan all link tables] Now scanning: $entryway (12 of 27)
22/03/2013 22:44:06 [Insteon::ALDB_i2] $entryway reading ALDB at location: 0x0000
22/03/2013 22:44:06 MYLOG6: fmr_outside turned off, unsetting master timer for fmr_outside
22/03/2013 22:44:06 [Insteon_PLM] DEBUG2: Sending obj=$entryway; command=read_write_aldb; extra=000000000001000000000000000000 incurred delay of 0.22 seconds; starting hop-count: 2
22/03/2013 22:44:06 [Insteon_PLM] DEBUG3: Sending PLM raw data: 02620f23021a2f000000000001000000000000000000
22/03/2013 22:44:06 [Insteon_PLM] DEBUG3: Received PLM raw data: 02620f23021a2f00000000000100000000000000000006
22/03/2013 22:44:06 [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$entryway; command=read_write_aldb; extra=000000000001000000000000000000
22/03/2013 22:44:07 [Insteon_PLM] DEBUG3: Received PLM raw data: 02500f230218d4ce262f0002510f230218d4ce112f0001010fff01a2040e0749ff000000
22/03/2013 22:44:07 [Insteon::BaseInterface] DEBUG2: Message received with 1 hops left, delaying next transmit to avoid collisions with remaining hops.
22/03/2013 22:44:07 [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:read_write_aldb; type:direct; group:
22/03/2013 22:44:07 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $entryway
22/03/2013 22:44:07 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0000] received: 00 for _mem_activity=scan _mem_action=aldb_i2read
22/03/2013 22:44:07 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0000] received ack
22/03/2013 22:44:07 [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:read_write_aldb; type:direct; group:
22/03/2013 22:44:07 [Insteon::BaseInterface] Processing message for $entryway
22/03/2013 22:44:07 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $entryway
22/03/2013 22:44:07 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0000] received: 0001010fff01a2040e0749ff000000 for _mem_activity=scan _mem_action=aldb_i2readack
22/03/2013 22:44:07 [Insteon::ALDB_i2] $entryway reading ALDB at location: 0x0ff7
22/03/2013 22:44:07 [Insteon_PLM] DEBUG2: Sending obj=$entryway; command=read_write_aldb; extra=0000000ff701000000000000000000 incurred delay of 0.05 seconds; starting hop-count: 2
22/03/2013 22:44:07 [Insteon_PLM] DEBUG3: Sending PLM raw data: 02620f23021a2f0000000ff701000000000000000000
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM raw data: 02620f23021a2f0000000ff70100000000000000000006
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$entryway; command=read_write_aldb; extra=0000000ff701000000000000000000
22/03/2013 22:44:08 [Insteon_PLM] x10 sending code: P2 as insteon msg: ce00
22/03/2013 22:44:08 [Insteon_PLM] x10 sending code: PK as insteon msg: c380
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM raw data: 02500f230218d4ce262f00
22/03/2013 22:44:08 [Insteon::BaseInterface] DEBUG2: Message received with 1 hops left, delaying next transmit to avoid collisions with remaining hops.
22/03/2013 22:44:08 [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:read_write_aldb; type:direct; group:
22/03/2013 22:44:08 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $entryway
22/03/2013 22:44:08 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0ff7] received: 00 for _mem_activity=scan _mem_action=aldb_i2read
22/03/2013 22:44:08 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0ff7] received ack
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM raw data: 02510f230218d4ce112f0001010ff701a2040e0912ff000000
22/03/2013 22:44:08 [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:read_write_aldb; type:direct; group:
22/03/2013 22:44:08 [Insteon::BaseInterface] Processing message for $entryway
22/03/2013 22:44:08 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $entryway
22/03/2013 22:44:08 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0ff7] received: 0001010ff701a2040e0912ff000000 for _mem_activity=scan _mem_action=aldb_i2readack
22/03/2013 22:44:08 [Insteon::ALDB_i2] $entryway reading ALDB at location: 0x0fef
22/03/2013 22:44:08 [Insteon_PLM] DEBUG2: Sending ce00 incurred delay of 0.61 seconds; starting hop-count: ?
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Sending PLM raw data: 0263ce00
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM raw data: 0263ce0006
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM acknowledge: ce00
22/03/2013 22:44:09 [Insteon_PLM] DEBUG2: Sending c380 incurred delay of 1.15 seconds; starting hop-count: ?
22/03/2013 22:44:09 [Insteon_PLM] DEBUG3: Sending PLM raw data: 0263c380
22/03/2013 22:44:09 [Insteon_PLM] DEBUG3: Received PLM raw data: 15
22/03/2013 22:44:09 [Insteon_PLM] DEBUG3: Interface extremely busy. Resending command after delaying for 1 second
22/03/2013 22:44:10 [Insteon::BaseMessage] WARN: now resending c380 after 1 attempts.
22/03/2013 22:44:06 [Insteon::BaseInterface] DEBUG2: Message received with 2 hops left, delaying next transmit to avoid collisions with remaining hops.
22/03/2013 22:44:06 [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:assign_to_group; type:direct; group:
22/03/2013 22:44:06 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $fmr_outside
22/03/2013 22:44:06 [Insteon::BaseObject] received status for $fmr_outside with on-level: 0%, hops left: 2
22/03/2013 22:44:06 [Insteon::BaseObject] The Link Table Version for $fmr_outside has been updated to version number 01
22/03/2013 22:44:06 [Scan all link tables] Now scanning: $entryway (12 of 27)
22/03/2013 22:44:06 [Insteon::ALDB_i2] $entryway reading ALDB at location: 0x0000
22/03/2013 22:44:06 MYLOG6: fmr_outside turned off, unsetting master timer for fmr_outside
22/03/2013 22:44:06 [Insteon_PLM] DEBUG2: Sending obj=$entryway; command=read_write_aldb; extra=000000000001000000000000000000 incurred delay of 0.22 seconds; starting hop-count: 2
22/03/2013 22:44:06 [Insteon_PLM] DEBUG3: Sending PLM raw data: 02620f23021a2f000000000001000000000000000000
22/03/2013 22:44:06 [Insteon_PLM] DEBUG3: Received PLM raw data: 02620f23021a2f00000000000100000000000000000006
22/03/2013 22:44:06 [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$entryway; command=read_write_aldb; extra=000000000001000000000000000000
22/03/2013 22:44:07 [Insteon_PLM] DEBUG3: Received PLM raw data: 02500f230218d4ce262f0002510f230218d4ce112f0001010fff01a2040e0749ff000000
22/03/2013 22:44:07 [Insteon::BaseInterface] DEBUG2: Message received with 1 hops left, delaying next transmit to avoid collisions with remaining hops.
22/03/2013 22:44:07 [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:read_write_aldb; type:direct; group:
22/03/2013 22:44:07 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $entryway
22/03/2013 22:44:07 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0000] received: 00 for _mem_activity=scan _mem_action=aldb_i2read
22/03/2013 22:44:07 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0000] received ack
22/03/2013 22:44:07 [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:read_write_aldb; type:direct; group:
22/03/2013 22:44:07 [Insteon::BaseInterface] Processing message for $entryway
22/03/2013 22:44:07 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $entryway
22/03/2013 22:44:07 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0000] received: 0001010fff01a2040e0749ff000000 for _mem_activity=scan _mem_action=aldb_i2readack
22/03/2013 22:44:07 [Insteon::ALDB_i2] $entryway reading ALDB at location: 0x0ff7
22/03/2013 22:44:07 [Insteon_PLM] DEBUG2: Sending obj=$entryway; command=read_write_aldb; extra=0000000ff701000000000000000000 incurred delay of 0.05 seconds; starting hop-count: 2
22/03/2013 22:44:07 [Insteon_PLM] DEBUG3: Sending PLM raw data: 02620f23021a2f0000000ff701000000000000000000
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM raw data: 02620f23021a2f0000000ff70100000000000000000006
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$entryway; command=read_write_aldb; extra=0000000ff701000000000000000000
22/03/2013 22:44:08 [Insteon_PLM] x10 sending code: P2 as insteon msg: ce00
22/03/2013 22:44:08 [Insteon_PLM] x10 sending code: PK as insteon msg: c380
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM raw data: 02500f230218d4ce262f00
22/03/2013 22:44:08 [Insteon::BaseInterface] DEBUG2: Message received with 1 hops left, delaying next transmit to avoid collisions with remaining hops.
22/03/2013 22:44:08 [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:read_write_aldb; type:direct; group:
22/03/2013 22:44:08 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $entryway
22/03/2013 22:44:08 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0ff7] received: 00 for _mem_activity=scan _mem_action=aldb_i2read
22/03/2013 22:44:08 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0ff7] received ack
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM raw data: 02510f230218d4ce112f0001010ff701a2040e0912ff000000
22/03/2013 22:44:08 [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:read_write_aldb; type:direct; group:
22/03/2013 22:44:08 [Insteon::BaseInterface] Processing message for $entryway
22/03/2013 22:44:08 [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $entryway
22/03/2013 22:44:08 [Insteon::ALDB_i2] DEBUG3: $entryway [0x0ff7] received: 0001010ff701a2040e0912ff000000 for _mem_activity=scan _mem_action=aldb_i2readack
22/03/2013 22:44:08 [Insteon::ALDB_i2] $entryway reading ALDB at location: 0x0fef
22/03/2013 22:44:08 [Insteon_PLM] DEBUG2: Sending ce00 incurred delay of 0.61 seconds; starting hop-count: ?
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Sending PLM raw data: 0263ce00
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM raw data: 0263ce0006
22/03/2013 22:44:08 [Insteon_PLM] DEBUG3: Received PLM acknowledge: ce00
22/03/2013 22:44:09 [Insteon_PLM] DEBUG2: Sending c380 incurred delay of 1.15 seconds; starting hop-count: ?
22/03/2013 22:44:09 [Insteon_PLM] DEBUG3: Sending PLM raw data: 0263c380
22/03/2013 22:44:09 [Insteon_PLM] DEBUG3: Received PLM raw data: 15
22/03/2013 22:44:09 [Insteon_PLM] DEBUG3: Interface extremely busy. Resending command after delaying for 1 second
22/03/2013 22:44:10 [Insteon::BaseMessage] WARN: now resending c380 after 1 attempts.

No logs were truncated before the first line. Looks like the error is related to the X10 command in the last log lines anyway, is it not?

[krkeegan]

This looks like it has something to do with how the no_hop_increase flag functions when it encounters an X10 message or device. I don't have X10 devices so there is a good chance there is a mistake here. I will look into this.

[marcmerlin]

I looked at the code, and yes, I had the bug again, and it happened the same way:
25/03/2013 14:29:16 [Insteon_PLM] DEBUG3: Received PLM raw data: 15
25/03/2013 14:29:16 [Insteon_PLM] DEBUG3: Interface extremely busy. Resending command after delaying for 1 second
25/03/2013 14:29:17 [Insteon::BaseMessage] WARN: now resending c380 after 1 attempts.
Can't call method "get_object_name" on an undefined value at ../lib/Insteon/Message.pm line 139.
at ./mh line 31
main::ANON('Can't call method "get_object_name" on an undefined value at...') called at ../lib/Insteon/Message.pm line 139

                    elsif (defined($$self{no_hop_increase}) && $main::Debug{insteon}){^M
                            &main::print_log("[Insteon::BaseMessage] Hop count not increased for "^M
                                    . $self->setby->get_object_name . " because no_hop_increase flag was set.");^M
                            $$self{no_hop_increase} = undef;^M

It looks like self->setby does not work for X10 devices, and in turn causes the new hop code to crash.

I can't test on demand because it only happens when X10 commands need to be resent, but this patch seems like it would at least stop the crash:

--- a/lib/Insteon/Message.pm
+++ b/lib/Insteon/Message.pm
@@ -136,8 +136,10 @@ sub send
}
}
elsif (defined($$self{no_hop_increase}) && $main::Debug{insteon}){

•                           &main::print_log("[Insteon::BaseMessage] Hop count not increased for "
  

•                                   . $self->setby->get_object_name . " because no_hop_increase flag was set.");
  

•                           $_ = "";
  

•                           $_ = $self->setby->get_object_name if (defined $self->setby);
  

•                           &main::print_log("[Insteon::BaseMessage] Hop count not increased for $_"
  

•                                   ." because no_hop_increase flag was set.");
                          $$self{no_hop_increase} = undef;
                   }
           }
  

[marcmerlin]

--- a/lib/Insteon/Message.pm
+++ b/lib/Insteon/Message.pm
@@ -136,8 +136,10 @@ sub send
                                 }
                         }
                         elsif (defined($$self{no_hop_increase}) && $main::Debug{insteon}){
-                               &main::print_log("[Insteon::BaseMessage] Hop count not increased for "
-                                       . $self->setby->get_object_name . " because no_hop_increase flag was set.");
+                               $_ = "";
+                               $_ = $self->setby->get_object_name if (defined $self->setby);
+                               &main::print_log("[Insteon::BaseMessage] Hop count not increased for $_"
+                                       ." because no_hop_increase flag was set.");
                                $$self{no_hop_increase} = undef;
                         }
                 }

[krkeegan]

yeah, there is no reason to even concern ourselves with hops and X10 messages anyways. To make the mod even shorter the elsif statement can just be amended to read

elsif (defined($$self{no_hop_increase}) && $main::Debug{insteon} && $self->setby->isa('Insteon::BaseObject'))

or it can even read

elsif (defined($$self{no_hop_increase}) && $main::Debug{insteon} && defined($self->setby))

if you like. Although, making sure setby is an Insteon::BaseObject might be preferable just in case we add some further future packet type. I am thinking of the zigbee/x10/insteon device sold by simplehome or whoever.