Insteon: Sync Failure Callback is Broken Again

[krkeegan]

I likely caused this somewhere, but the bug is rather henious:

30/04/2013 16:48:22  [Insteon::BaseInterface] Received message from: $upstairs_thermo; command: status_humid; type: direct; group: 
30/04/2013 16:48:22  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $upstairs_thermo
30/04/2013 16:48:22  [Insteon::Thermo_i2] Received Status Humid Message for $upstairs_thermo
30/04/2013 16:48:23  [Insteon::BaseInterface] WARN: number of retries (10) for obj=$f_kt_pantry_lt_ma; command=peek; extra=FB exceeds limit.  Now moving on...
30/04/2013 16:48:23  [Insteon::BaseInterface] WARN: Message Timeout:  Now calling callback: &Insteon::_get_next_linkscan_failure(0)
30/04/2013 16:48:23  [Scan all link tables] WARN: failure occurred when scanning $f_kt_pantry_lt_ma.  Moving on...
30/04/2013 16:48:23  [Scan all link tables] Now scanning: $f_kt_sink_lt_ma (12 of 64)
30/04/2013 16:48:23  [Insteon::ALDB_i1] $f_kt_sink_lt_ma accessing memory at location: 0x0FF8
30/04/2013 16:48:23  [Insteon::BaseInterface] WARN: number of retries (10) for obj=$f_kt_pantry_lt_ma; command=peek; extra=FB exceeds limit.  Now moving on...
30/04/2013 16:48:23  [Insteon::BaseInterface] WARN: Message Timeout:  Now calling callback: &Insteon::_get_next_linkscan_failure(0)
30/04/2013 16:48:23  [Scan all link tables] WARN: failure occurred when scanning $f_kt_sink_lt_ma.  Moving on...
30/04/2013 16:48:23  [Scan all link tables] Now scanning: $f_kt_pad_lt_s0 (13 of 64)
30/04/2013 16:48:23  [Insteon::ALDB_i1] $f_kt_pad_lt_s0 accessing memory at location: 0x0FF8
30/04/2013 16:48:23  [Insteon::BaseInterface] WARN: number of retries (10) for obj=$f_kt_pantry_lt_ma; command=peek; extra=FB exceeds limit.  Now moving on...
30/04/2013 16:48:23  [Insteon::BaseInterface] WARN: Message Timeout:  Now calling callback: &Insteon::_get_next_linkscan_failure(0)
30/04/2013 16:48:23  [Scan all link tables] WARN: failure occurred when scanning $f_kt_pad_lt_s0.  Moving on...
30/04/2013 16:48:23  [Scan all link tables] Now scanning: $f_en_lt_s1 (14 of 64)
30/04/2013 16:48:23  [Insteon::ALDB_i1] $f_en_lt_s1 accessing memory at location: 0x0FF8
30/04/2013 16:48:23  [Insteon::BaseInterface] WARN: number of retries (10) for obj=$f_kt_pantry_lt_ma; command=peek; extra=FB exceeds limit.  Now moving on...
30/04/2013 16:48:23  [Insteon::BaseInterface] WARN: Message Timeout:  Now calling callback: &Insteon::_get_next_linkscan_failure(0)
30/04/2013 16:48:23  [Scan all link tables] WARN: failure occurred when scanning $f_en_lt_s1.  Moving on...
30/04/2013 16:48:23  [Scan all link tables] Now scanning: $f_en_lt_ma (15 of 64)
30/04/2013 16:48:23  [Insteon::ALDB_i1] $f_en_lt_ma accessing memory at location: 0x0FF8
30/04/2013 16:48:23  [Insteon::BaseInterface] WARN: number of retries (10) for obj=$f_kt_pantry_lt_ma; command=peek; extra=FB exceeds limit.  Now moving on...
30/04/2013 16:48:23  [Insteon::BaseInterface] WARN: Message Timeout:  Now calling callback: &Insteon::_get_next_linkscan_failure(0)

I looks like the failure callback is being called improperly at some point. If I had to guess, it looks like the message timeout sub is calling it as well as something else.

[krkeegan]

This was caused by a change in SHA 058f80e

[mstovenour]

yes. I found that this weekend as well. moving the call to clear_active_message in sub process_queue causes it. reverting just that one change fixes the issue in your log. I'll need to research how to handle a NAC for an un linked I2CS device.

Michael