Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add Support for Insteon iMeter Solo and SynchroLinc #374

Merged
merged 6 commits into from
Mar 25, 2014

Conversation

krkeegan
Copy link
Collaborator

I coded this without having the devices on hand, so I can't be sure it works. I was only able to test to make sure that the MH code was stable.

I added support for everything I know about these devices, but there may be features that I was not able to discover from my web searches.

If anyone has one of these, I would be interested to know how this works. Both devices are very different from the normal Insteon type devices.

Fixes #372

@rudybrian
Copy link
Contributor

Thanks so much for this @krkeegan!

I finally had a chance to poke at this today and wanted to share my findings.

Initial testing shows the code can read the iMeter on initial startup:

03/06/2014 15:02:55 [Insteon::iMeter] received status for $miner_power3. Current Usage: 386/watts Accumulated Usage: 2203.32917638889/kWh Hops left: 2

Setting the device state to refresh yeilds:

03/06/2014 15:20:00 [Insteon::BaseObject] failed state validation with state=refresh

which is likely related to when calling request_status() it doesn't seem to do anything.

I also noticed that get_power() was missing.

@krkeegan
Copy link
Collaborator Author

krkeegan commented Mar 6, 2014

Oops, forgot that I need to add a special derive_state routine so that "refresh" will work. Shouldn't be a big deal.

What do you mean "get_power" is missing. I assume you are trying to get the instantaneous usage? If so simply calling request_status, to get the value, and then retreiving the value from $miner_power3->state will do it. The state of the device should be the instantaneous power value.

Also, is $miner_power3 a crypto-currency miner? Seems like a good way to figure out the returns on your electricity usage.

@rudybrian
Copy link
Contributor

No worries @krkeegan...

My original code had a get_power() function which returned just the instantaneous power value ($$self{'power'}), and get_accumenergy() which returned the accumulated power usage ($$self{'accumenergy'}) and I noticed you had a corresponding get_accumulated_usage() function that does the same thing as get_accumenergy(), but the equivalent of get_power() seemed to be missing for functional parity.

$miner_power3 is indeed a cryptocurrency miner and it's predecessor was the inspiration for me to develop the original iMeter support code.

@krkeegan
Copy link
Collaborator Author

Brian, I added back in the get_power function.

I also fixed up the code so that "refresh" should work.

Let me know if that fixes things for you.

@rudybrian
Copy link
Contributor

Here is what I am seeing beginning with startup (with insteon debugging enabled this time):

03/10/2014 16:20:01  [Insteon::BaseObject] received engine version for $miner_power3 of I2. hops left: 0
03/10/2014 16:20:01  [Insteon::iMeter] ACK Received for $miner_power3
03/10/2014 16:20:01  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:; type:direct; group:
03/10/2014 16:20:01  [Insteon::BaseObject] Ignoring unsupported command from $miner_power3
03/10/2014 16:20:03  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 1 attempts.
03/10/2014 16:20:03  [Insteon::iMeter] ACK Received for $miner_power3
03/10/2014 16:20:03  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/10/2014 16:20:03  [Insteon::iMeter] received status for $miner_power3. Current Usage: 380/watts Accumulated Usage: 2244.17/kWh Hops left: 2
03/10/2014 16:20:03  [Insteon::BaseObject] $miner_power3::set_receive(on, $miner_power3)
03/10/2014 16:21:00  Reading iMeter (scheduled)
03/10/2014 16:22:00  Reading iMeter (scheduled)
03/10/2014 16:22:37  Running: miner power3 status

The Reading iMeter (scheduled) log event indicates when some user code fires every minute and calls $miner_power3->request_status(). Requesting status or refreshing (from the web interface) also doesn't seem to have an effect (but there isn't an error this time)

@rudybrian
Copy link
Contributor

Here is another log extract with the debug level for insteon set all the way to 4:

03/12/2014 13:47:33  [Insteon] Setting up initialization hooks
03/12/2014 13:47:33  [Insteon_PLM] setting default xmit delay to: 0.25
03/12/2014 13:47:33  [Insteon_PLM] setting x10 xmit delay to: 0.5

Good code saved
03/12/2014 13:47:33  running: aplay ./../sounds/sound_click1.wav

Restoring object states
Object states restored
03/12/2014 13:47:33  [Insteon] DEBUG4 Checking aldb version of all devices
03/12/2014 13:47:33  [Insteon] DEBUG4 Checking aldb version for $miner_power3 (1 of 1)
03/12/2014 13:47:33  [Insteon::BaseDevice] DEBUG4: aldb_version is I1 but device is I2.  Remapping aldb version to I2
03/12/2014 13:47:33  [Insteon] DEBUG4 Checking aldb version of all devices completed
03/12/2014 13:47:33  [Insteon_PLM] DEBUG2: Sending obj=$PLM; interface_data= incurred delay of 0.00 seconds; starting hop-count: ?
03/12/2014 13:47:33  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0260
03/12/2014 13:47:33  [Insteon_PLM] DEBUG4:
         PLM Command: (0260) plm_info

03/12/2014 13:47:33  [Insteon] DEBUG4 Initializing thermostat versions
03/12/2014 13:47:33  Generating Voice commands for all Insteon objects
Activating voice commands
Starting monitor commands loop
...
03/12/2014 13:47:33  [Insteon_PLM] DEBUG3: Received PLM raw data: 0260148625
03/12/2014 13:47:33  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 0260148625
03/12/2014 13:47:33  Rereading .menu code files.
03/12/2014 13:47:33  Organizer: Calendar matches target schema and does not require upgrading
03/12/2014 13:47:33  Organizer: Todo matches target schema and does not require upgrading
03/12/2014 13:47:33  Organizer: Reading updated organizer calendar file now
03/12/2014 13:47:33  Evaluating code organizer_events
03/12/2014 13:47:33  Organizer: Reading updated organizer todo file
03/12/2014 13:47:33  Evaluating code organizer_tasks
03/12/2014 13:47:33  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 0260148625
03/12/2014 13:47:33  [Insteon_PLM] DEBUG3: Received PLM raw data: 026014862503159206
03/12/2014 13:47:33  [Insteon_PLM] DEBUG4:
         PLM Command: (0260) plm_info
       PLM Device ID: 14:86:25
     Device Category: 03:15
            Firmware: 92
        PLM Response: (06) ACK

03/12/2014 13:47:33  [Insteon_PLM] PLM id: 148625 firmware: 92
03/12/2014 13:47:34  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=get_engine_version incurred delay of 0.28 seconds; starting hop-count: 1
03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876050d00
03/12/2014 13:47:34  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 0d00
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: 00

03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Received PLM raw data: 0262198876050d0006
03/12/2014 13:47:34  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 0d00
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: 00
        PLM Response: (06) ACK

03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=get_engine_version
03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625210d01
03/12/2014 13:47:34  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 0d01
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: (01) i2

03/12/2014 13:47:34  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:get_engine_version; type:direct; group:
03/12/2014 13:47:34  [Insteon::BaseObject] received engine version for $miner_power3 of I2. hops left: 0
03/12/2014 13:47:34  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.58 seconds; starting hop-count: 1
03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/12/2014 13:47:34  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/12/2014 13:47:34  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
        PLM Response: (06) ACK

03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/12/2014 13:47:34  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/12/2014 13:47:34  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/12/2014 13:47:34  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/12/2014 13:47:34  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=11
03/12/2014 13:47:34  [Insteon::iMeter] ACK Received for $miner_power3
03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8800001f
03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 02511988761486251b8800001f
03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02511988761486251b8800001f
03/12/2014 13:47:34  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8800001f01050290012133d1cd2e32cf
03/12/2014 13:47:34  [Insteon_PLM] DEBUG4:
         PLM Command: (0251) insteon_ext_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 1b
                Message Type: (000) Direct Message
              Message Length: (1) Extended Length
                   Hops Left: 2
                    Max Hops: 3
         Insteon Message: 8800001f01050290012133d1cd2e32cf
                       Cmd 1: 88 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 001f01050290012133d1cd2e32cf

03/12/2014 13:47:34  [Insteon::BaseInterface] DEBUG3: Message received with 2 hops left, plus ACK will take 3 to deliver, delaying next transmit by 1050 milliseconds to avoid collisions.
03/12/2014 13:47:34  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:; type:direct; group:
03/12/2014 13:47:34  [Insteon::BaseInterface] Processing message for $miner_power3
03/12/2014 13:47:34  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/12/2014 13:47:34  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=111
03/12/2014 13:47:34  [Insteon::BaseObject] Ignoring unsupported command from $miner_power3
Playing WAVE './../sounds/sound_click1.wav' : Unsigned 8 bit, Rate 22050 Hz, Mono
03/12/2014 13:47:36  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 1 attempts.
03/12/2014 13:47:36  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
03/12/2014 13:47:36  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=2111
03/12/2014 13:47:36  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 2.32 seconds; starting hop-count: 1
03/12/2014 13:47:36  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/12/2014 13:47:36  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/12/2014 13:47:36  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/12/2014 13:47:36  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
        PLM Response: (06) ACK

03/12/2014 13:47:36  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/12/2014 13:47:36  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/12/2014 13:47:36  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/12/2014 13:47:36  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/12/2014 13:47:36  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/12/2014 13:47:36  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=12111
03/12/2014 13:47:36  [Insteon::iMeter] ACK Received for $miner_power3
03/12/2014 13:47:36  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200025601060280016d0071da6e3334
03/12/2014 13:47:36  [Insteon_PLM] DEBUG4:
         PLM Command: (0251) insteon_ext_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 1b
                Message Type: (000) Direct Message
              Message Length: (1) Extended Length
                   Hops Left: 2
                    Max Hops: 3
         Insteon Message: 8200025601060280016d0071da6e3334
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 025601060280016d0071da6e3334

03/12/2014 13:47:36  [Insteon::BaseInterface] DEBUG3: Message received with 2 hops left, plus ACK will take 3 to deliver, delaying next transmit by 1050 milliseconds to avoid collisions.
03/12/2014 13:47:36  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/12/2014 13:47:36  [Insteon::BaseInterface] Processing message for $miner_power3
03/12/2014 13:47:36  [Insteon::iMeter] received status for $miner_power3. Current Usage: 365/watts Accumulated Usage: 2263.84/kWh Hops left: 2
03/12/2014 13:47:36  [Insteon::BaseObject] $miner_power3::set_receive(on, $miner_power3)
03/12/2014 13:48:00  Reading iMeter (scheduled)
03/12/2014 13:48:18  Running: miner power3 status
03/12/2014 13:48:29  Running: miner power3 log accumulated usage
03/12/2014 13:48:29  [Insteon::iMeter] Current values for $miner_power3. Current Usage: 365/watts Accumulated Usage: 2263.84/kWh
03/12/2014 13:48:49  Running: Read iMeter
03/12/2014 13:48:49  Reading iMeter
03/12/2014 13:49:00  Reading iMeter (scheduled)

It would appear that despite calling request_status() after the device is first initialized, no Insteon command is actually being sent.

@krkeegan
Copy link
Collaborator Author

Hmm, odd. It is working, but it seems to be throwing an odd message back at us every now and then.

First, this entry in the first log:

03/10/2014 16:20:01  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:; type:direct; group:
03/10/2014 16:20:01  [Insteon::BaseObject] Ignoring unsupported command from $miner_power3
03/10/2014 16:20:03  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 1 attempts.
03/10/2014 16:20:03  [Insteon::iMeter] ACK Received for $miner_power3
03/10/2014 16:20:03  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/10/2014 16:20:03  [Insteon::iMeter] received status for $miner_power3. Current Usage: 380/watts Accumulated Usage: 2244.17/kWh Hops left: 2

Is odd. When MH starts up, it sends a request_status command to each device. In this excerpt, it is sending the command to the iMeter. The iMeter responds with some unknown command, MH then tries again, and the iMeter responds in a way we understand. This produces the final status line. So request_status is working.

To further compound the oddity, the second log seems to show that this unknown command is repeatable. MH starts up and goes through the same process and we get similar results, including the odd first response, but a legitimate response on the second attempt. From the extended log, we can see that the odd response back is:

03/12/2014 13:47:34  [Insteon_PLM] DEBUG4:
         PLM Command: (0251) insteon_ext_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 1b
                Message Type: (000) Direct Message
              Message Length: (1) Extended Length
                   Hops Left: 2
                    Max Hops: 3
         Insteon Message: 8800001f01050290012133d1cd2e32cf
                       Cmd 1: 88 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 001f01050290012133d1cd2e32cf

We expect Cmd1 to be 0x82 not 0x88. The rest of the values in D1-D14 also don't quite work. The power level would be 289 watts, the accumulated energy would be 263,774.60/kWh. It looks like this message means something else. What I don't know, nor do I know why the iMeter seems to be responding with this message for the first response to request_status.

Now, why isn't your code causing request_status to run? I don't know. Try running the voice command 'status' on the device and see what happens. That certainly works for me. Similarly, setting the state of the device to 'refresh' also causes request_status to run for me.

I did fix one glitch last night which was preventing the state of the object from being set to the Power Value.

@krkeegan
Copy link
Collaborator Author

This post seems to suggest that the iMeter sends out spurious 0x88 messages every now and then:

http://forum.universal-devices.com/viewtopic.php?p=47621&sid=e4949f24fb08e8b95b1e4a053ff8db64#p47621

@rudybrian
Copy link
Contributor

Thanks @krkeegan,

The 0x88 message is indeed odd and unexpected. I was simply ignoring them in my original code, so I didn't even notice them until now.

I have indeed set the state of the device to refresh, as well as invoking the status voice command to no avail. Here is an excerpt from my user code:

$v_query_imeter    = new Voice_Cmd 'Read iMeter';
$v_reset_imeter    = new Voice_Cmd 'Reset iMeter accumulated usage';

$v_get_imeter_power    = new Voice_Cmd 'Get iMeter power';
$v_get_imeter_accumulated_usage    = new Voice_Cmd 'Get iMeter accumulated usage';


if ($state = said $v_query_imeter) {
        print_log "Reading iMeter";
        $miner_power3->request_status();
}

if ($state = said $v_reset_imeter) {
        print_log "Resetting iMeter accumulated energy";
        $miner_power3->reset_accumulated_usage();
}

# Poll for changes every 1 minute
if (new_minute 1) {
        print_log "Reading iMeter (scheduled)";
        $miner_power3->request_status();
}

if ($state = said $v_get_imeter_power) {
        print_log "Power is " . $miner_power3->get_power() . "W";
        respond $miner_power3->get_power() . "W";
}

if ($state = said $v_get_imeter_accumulated_usage) {
        print_log "Accumulated energy is " . $miner_power3->get_accumulated_usage() . "kWh";
        respond $miner_power3->get_accumulated_usage() . "kWh";
}

I added an additional debug statement to request_status() to see if it was actually getting called, and it does appear to be, but nothing is actually getting sent after the first imeter_query goes out.

sub request_status
{
        my ($self,$requestor) = @_;
        my $extra = '00';
        ::print_log("[Insteon::iMeter] sending imeter_query for " . $self->get_object_name) if $self->debuglevel(1, 'insteon');
    my $message = new Insteon::InsteonMessage('insteon_send', $self, 'imeter_query', $extra);
    $self->_send_cmd($message);
    return;
}
03/12/2014 17:19:45  [Insteon] DEBUG4 Checking aldb version of all devices
03/12/2014 17:19:45  [Insteon] DEBUG4 Checking aldb version for $miner_power3 (1 of 1)
03/12/2014 17:19:45  [Insteon::BaseDevice] DEBUG4: aldb_version is I1 but device is I2.  Remapping aldb version to I2
03/12/2014 17:19:45  [Insteon] DEBUG4 Checking aldb version of all devices completed
03/12/2014 17:19:45  [Insteon_PLM] DEBUG2: Sending obj=$PLM; interface_data= incurred delay of 0.00 seconds; starting hop-count: ?
03/12/2014 17:19:45  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0260
03/12/2014 17:19:45  [Insteon_PLM] DEBUG4:
         PLM Command: (0260) plm_info

03/12/2014 17:19:45  [Insteon::iMeter] sending imeter_query for $miner_power3
03/12/2014 17:19:45  [Insteon] DEBUG4 Initializing thermostat versions
03/12/2014 17:19:45  Generating Voice commands for all Insteon objects
Activating voice commands
Starting monitor commands loop

03/12/2014 17:19:45  [Insteon_PLM] DEBUG3: Received PLM raw data: 02
03/12/2014 17:19:45  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 02
03/12/2014 17:19:45  Rereading .menu code files.
03/12/2014 17:19:45  Organizer: Calendar matches target schema and does not require upgrading
03/12/2014 17:19:45  Organizer: Todo matches target schema and does not require upgrading
03/12/2014 17:19:45  Organizer: Reading updated organizer calendar file now
03/12/2014 17:19:45  Evaluating code organizer_events
03/12/2014 17:19:45  Organizer: Reading updated organizer todo file
03/12/2014 17:19:45  Evaluating code organizer_tasks
03/12/2014 17:19:45  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02
03/12/2014 17:19:45  [Insteon_PLM] DEBUG3: Received PLM raw data: 026014862503159206
03/12/2014 17:19:45  [Insteon_PLM] DEBUG4:
         PLM Command: (0260) plm_info
       PLM Device ID: 14:86:25
     Device Category: 03:15
            Firmware: 92
        PLM Response: (06) ACK

03/12/2014 17:19:45  [Insteon_PLM] PLM id: 148625 firmware: 92
03/12/2014 17:19:46  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=get_engine_version incurred delay of 0.28 seconds; starting hop-count: 1
03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876050d00
03/12/2014 17:19:46  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 0d00
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: 00

03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Received PLM raw data: 0262198876050d0006
03/12/2014 17:19:46  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 0d00
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: 00
        PLM Response: (06) ACK

03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=get_engine_version
03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625210d01
03/12/2014 17:19:46  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 0d01
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: (01) i2

03/12/2014 17:19:46  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:get_engine_version; type:direct; group:
03/12/2014 17:19:46  [Insteon::BaseObject] received engine version for $miner_power3 of I2. hops left: 0
03/12/2014 17:19:46  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.58 seconds; starting hop-count: 1
03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/12/2014 17:19:46  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/12/2014 17:19:46  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
        PLM Response: (06) ACK

03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/12/2014 17:19:46  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/12/2014 17:19:46  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/12/2014 17:19:46  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/12/2014 17:19:46  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=11
03/12/2014 17:19:46  [Insteon::iMeter] ACK Received for $miner_power3
03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8800001f01
03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 02511988761486251b8800001f01
03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02511988761486251b8800001f01
03/12/2014 17:19:46  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8800001f01050290012133d1cd2e32cf
03/12/2014 17:19:46  [Insteon_PLM] DEBUG4:
         PLM Command: (0251) insteon_ext_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 1b
                Message Type: (000) Direct Message
              Message Length: (1) Extended Length
                   Hops Left: 2
                    Max Hops: 3
         Insteon Message: 8800001f01050290012133d1cd2e32cf
                       Cmd 1: 88 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 001f01050290012133d1cd2e32cf

03/12/2014 17:19:46  [Insteon::BaseInterface] DEBUG3: Message received with 2 hops left, plus ACK will take 3 to deliver, delaying next transmit by 1050 milliseconds to avoid collisions.
03/12/2014 17:19:46  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:; type:direct; group:
03/12/2014 17:19:46  [Insteon::BaseInterface] Processing message for $miner_power3
03/12/2014 17:19:46  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/12/2014 17:19:46  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=111
03/12/2014 17:19:46  [Insteon::BaseObject] Ignoring unsupported command from $miner_power3
Playing WAVE './../sounds/sound_click1.wav' : Unsigned 8 bit, Rate 22050 Hz, Mono
03/12/2014 17:19:48  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 1 attempts.
03/12/2014 17:19:48  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
03/12/2014 17:19:48  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=2111
03/12/2014 17:19:48  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 2.32 seconds; starting hop-count: 1
03/12/2014 17:19:48  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/12/2014 17:19:48  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/12/2014 17:19:48  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/12/2014 17:19:48  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
        PLM Response: (06) ACK

03/12/2014 17:19:48  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/12/2014 17:19:48  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/12/2014 17:19:48  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/12/2014 17:19:48  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/12/2014 17:19:48  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/12/2014 17:19:48  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=12111
03/12/2014 17:19:48  [Insteon::iMeter] ACK Received for $miner_power3
03/12/2014 17:19:48  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200025a01060280017b0071eb3126a0
03/12/2014 17:19:48  [Insteon_PLM] DEBUG4:
         PLM Command: (0251) insteon_ext_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 1b
                Message Type: (000) Direct Message
              Message Length: (1) Extended Length
                   Hops Left: 2
                    Max Hops: 3
         Insteon Message: 8200025a01060280017b0071eb3126a0
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 025a01060280017b0071eb3126a0

03/12/2014 17:19:48  [Insteon::BaseInterface] DEBUG3: Message received with 2 hops left, plus ACK will take 3 to deliver, delaying next transmit by 1050 milliseconds to avoid collisions.
03/12/2014 17:19:48  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/12/2014 17:19:48  [Insteon::BaseInterface] Processing message for $miner_power3
03/12/2014 17:19:48  [Insteon::iMeter] received status for $miner_power3. Current Usage: 379/watts Accumulated Usage: 2265.14/kWh Hops left: 2

03/12/2014 17:20:00  Reading iMeter (scheduled)
03/12/2014 17:20:00  [Insteon::iMeter] sending imeter_query for $miner_power3
03/12/2014 17:20:59  Running: miner power3 status
03/12/2014 17:20:59  [Insteon::iMeter] sending imeter_query for $miner_power3
03/12/2014 17:21:00  Reading iMeter (scheduled)
03/12/2014 17:21:00  [Insteon::iMeter] sending imeter_query for $miner_power3
03/12/2014 17:21:17  Running: Read iMeter
03/12/2014 17:21:17  Reading iMeter
03/12/2014 17:21:17  [Insteon::iMeter] sending imeter_query for $miner_power3

@krkeegan
Copy link
Collaborator Author

Hmm, maybe the current message is never getting cleared.

@rudybrian
Copy link
Contributor

I was thinking the same thing, but haven't yet wrapped my head around how everything with the new Insteon code works to find out why.

@krkeegan
Copy link
Collaborator Author

OK, I think that my last commit should solve it. Sorry about all the testing, not having a device really makes coding more difficult.

@rudybrian
Copy link
Contributor

Thanks @krkeegan, that seems to have done it!

I had to make a minor change to my user code to properly trigger off the state change, but all appears to be working now.

From

if (state_now $miner_power3 eq 'power_change') {

To

if ($state = state_now $miner_power3) {

FYI: I also verified that reset_accumulated_usage() is working as expected.

@rudybrian
Copy link
Contributor

I ran a few longer tests today as I was merging in my old user code into a new MH install and after running for 20-30 minutes I stopped getting iMeter updates. I'm not sure if this is due to those spurious 0x88 messages, but wanted to report it here. I'll try to do more testing over the weekend with the log level cranked up to see if it helps expose what is happening.

@hollie hollie added this to the Next stable 3.1 milestone Mar 15, 2014
@rudybrian
Copy link
Contributor

I ran another test overnight starting Friday night into Saturday, and eventually the issue re-occurred. I stopped the test only a few minutes after noticing it, but hopefully there is enough here to be helpful:

03/15/2014 11:23:00  Reading iMeter (scheduled)
03/15/2014 11:23:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/15/2014 11:23:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/15/2014 11:23:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:23:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/15/2014 11:23:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
        PLM Response: (06) ACK

03/15/2014 11:23:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/15/2014 11:23:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/15/2014 11:23:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:23:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/15/2014 11:23:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/15/2014 11:23:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1111111211
03/15/2014 11:23:00  [Insteon::iMeter] ACK Received for $miner_power3
03/15/2014 11:23:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200038401010290
03/15/2014 11:23:00  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 02511988761486251b8200038401010290
03/15/2014 11:23:00  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02511988761486251b8200038401010290
03/15/2014 11:23:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200038401010290020700010169cdc0
03/15/2014 11:23:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0251) insteon_ext_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 1b
                Message Type: (000) Direct Message
              Message Length: (1) Extended Length
                   Hops Left: 2
                    Max Hops: 3
         Insteon Message: 8200038401010290020700010169cdc0
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 038401010290020700010169cdc0

03/15/2014 11:23:00  [Insteon::BaseInterface] DEBUG3: Message received with 2 hops left, plus ACK will take 3 to deliver, delaying next transmit by 1050 milliseconds to avoid collisions.
03/15/2014 11:23:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/15/2014 11:23:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/15/2014 11:23:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 519/watts Accumulated Usage: 19.99/kWh Hops left: 2
03/15/2014 11:23:00  iMeter power has changed:519W, 19.99kWh
03/15/2014 11:24:00  Reading iMeter (scheduled)
03/15/2014 11:24:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/15/2014 11:24:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/15/2014 11:24:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:24:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/15/2014 11:24:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
        PLM Response: (06) ACK

03/15/2014 11:24:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/15/2014 11:24:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/15/2014 11:24:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:24:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/15/2014 11:24:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/15/2014 11:24:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1111111121
03/15/2014 11:24:00  [Insteon::iMeter] ACK Received for $miner_power3
03/15/2014 11:24:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b820003560102028001f30001018375b7
03/15/2014 11:24:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0251) insteon_ext_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 1b
                Message Type: (000) Direct Message
              Message Length: (1) Extended Length
                   Hops Left: 2
                    Max Hops: 3
         Insteon Message: 820003560102028001f30001018375b7
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 03560102028001f30001018375b7

03/15/2014 11:24:00  [Insteon::BaseInterface] DEBUG3: Message received with 2 hops left, plus ACK will take 3 to deliver, delaying next transmit by 1050 milliseconds to avoid collisions.
03/15/2014 11:24:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/15/2014 11:24:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/15/2014 11:24:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 499/watts Accumulated Usage: 20.00/kWh Hops left: 2
03/15/2014 11:24:00  iMeter power has changed:499W, 20.00kWh
03/15/2014 11:25:00  Reading iMeter (scheduled)
03/15/2014 11:25:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/15/2014 11:25:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/15/2014 11:25:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:25:01  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 1 attempts.
03/15/2014 11:25:01  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
03/15/2014 11:25:01  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=2111111112
03/15/2014 11:25:01  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 1.75 seconds; starting hop-count: 1
03/15/2014 11:25:01  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/15/2014 11:25:01  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:25:03  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 2 attempts.
03/15/2014 11:25:03  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
03/15/2014 11:25:03  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=2211111111
03/15/2014 11:25:03  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 3.45 seconds; starting hop-count: 1
03/15/2014 11:25:03  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/15/2014 11:25:03  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:25:05  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 3 attempts.
03/15/2014 11:25:05  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
03/15/2014 11:25:05  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=2221111111
03/15/2014 11:25:05  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 5.16 seconds; starting hop-count: 1
03/15/2014 11:25:05  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/15/2014 11:25:05  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:25:06  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 4 attempts.
03/15/2014 11:25:06  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
03/15/2014 11:25:06  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=2222111111
03/15/2014 11:25:06  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 6.90 seconds; starting hop-count: 1
03/15/2014 11:25:06  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/15/2014 11:25:06  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:25:08  [Insteon::BaseInterface] WARN: number of retries (5) for obj=$miner_power3; command=imeter_query; extra=00 exceeds limit.  Now moving on...
03/15/2014 11:26:00  Reading iMeter (scheduled)
03/15/2014 11:26:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/15/2014 11:26:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/15/2014 11:26:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:26:01  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 1 attempts.
03/15/2014 11:26:01  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
03/15/2014 11:26:01  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=2 :: hop_array[]=2222211111
03/15/2014 11:26:01  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 1.71 seconds; starting hop-count: 2
03/15/2014 11:26:01  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 02621988760a8200
03/15/2014 11:26:01  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 0a
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 2
                    Max Hops: 2
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:26:03  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 2 attempts.
03/15/2014 11:26:03  [Insteon::BaseObject] DEBUG3: Adding hop count of 3 to hop_array of $miner_power3
03/15/2014 11:26:03  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=2 :: hop_array[]=3222221111
03/15/2014 11:26:03  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 3.62 seconds; starting hop-count: 2
03/15/2014 11:26:03  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 02621988760a8200
03/15/2014 11:26:03  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 0a
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 2
                    Max Hops: 2
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:26:05  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 3 attempts.
03/15/2014 11:26:05  [Insteon::BaseObject] DEBUG3: Adding hop count of 3 to hop_array of $miner_power3
03/15/2014 11:26:05  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=2 :: hop_array[]=3322222111
03/15/2014 11:26:05  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 5.53 seconds; starting hop-count: 2
03/15/2014 11:26:05  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 02621988760a8200
03/15/2014 11:26:05  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 0a
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 2
                    Max Hops: 2
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:26:07  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 4 attempts.
03/15/2014 11:26:07  [Insteon::BaseObject] DEBUG3: Adding hop count of 3 to hop_array of $miner_power3
03/15/2014 11:26:07  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=2 :: hop_array[]=3332222211
03/15/2014 11:26:07  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 7.45 seconds; starting hop-count: 2
03/15/2014 11:26:07  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 02621988760a8200
03/15/2014 11:26:07  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 0a
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 2
                    Max Hops: 2
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/15/2014 11:26:09  [Insteon::BaseInterface] WARN: number of retries (5) for obj=$miner_power3; command=imeter_query; extra=00 exceeds limit.  Now moving on...

@krkeegan
Copy link
Collaborator Author

So what happens to the rest of MH after this happens?

At 11:25:00, MH sends the iMeter request. However, the PLM doesn't acknowledge receiving anything. MH retries 5 times, and the PLM never responds in any way. This is not normal, in fact I have never seen this. The PLM should always respond to receiving data, in the worst case, the PLM will balk at the command with a 15 NACK response.

What happens if you try and send other commands once this state has been reached? Does the PLM ever wake back up again? Do you have some sort of exotic connection to your PLM?

@rudybrian
Copy link
Contributor

Hi @krkeegan,

Unfortunately I terminated MH after the last log line shown in my post. The web interface was responsive before I terminated MH, and otherwise it seemed to be working properly.

I didn't have any other Insteon devices on the powerline during the test apart from the iMeter, but will do so during the next test run.

As far as an exotic connection to the PLM goes no. I have the PLM on a USB 2.0 hub on the USB 2.0 port on my CentOS 6.4 box. Other USB devices connected via this hub were working properly w/o interruption during this time.

@krkeegan
Copy link
Collaborator Author

Yes, MH itself should continue to operate normally. I am curious to know if the PLM would respond to a different command? Or a different device?

PLM lockups did happen in the past. For the most part, I think we overcame them 6-8 months ago by being more careful with our message handling. To my knowledge, when they did happen, they looked a lot like what you are seeing.

I don't see anything in particular that would cause a lockup to occur. Sending a status_request every minute creates more traffic than normal, but it shouldn't be an issue. I have a script that sends a status_request to a different device that rotates every minute. This is similar and hasn't cause me any issued. However, I do wonder whether the PLM has some sort of "de-deuplication" inside of it that is causing it to ignore repeated messages in some manner.

@rudybrian
Copy link
Contributor

I captured logs from another test run and was able to get it to fail again, but this time it appears to have done so differently than last time. For some reason this time request_status() stops sending messages to the PLM as though the message wasn't being removed from the command stack. This may be related to the all_link_clean_status that happens at 12:47.

03/18/2014 12:45:00  Reading iMeter (scheduled)
03/18/2014 12:45:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/18/2014 12:45:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/18/2014 12:45:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/18/2014 12:45:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0262198876058200060250198876148625218200
03/18/2014 12:45:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
        PLM Response: (06) ACK

03/18/2014 12:45:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/18/2014 12:45:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/18/2014 12:45:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/18/2014 12:45:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/18/2014 12:45:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1111111111
03/18/2014 12:45:00  [Insteon::iMeter] ACK Received for $miner_power3
03/18/2014 12:45:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200025d01050280016a00029a9ea6b9
03/18/2014 12:45:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0251) insteon_ext_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 1b
                Message Type: (000) Direct Message
              Message Length: (1) Extended Length
                   Hops Left: 2
                    Max Hops: 3
         Insteon Message: 8200025d01050280016a00029a9ea6b9
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 025d01050280016a00029a9ea6b9

03/18/2014 12:45:00  [Insteon::BaseInterface] DEBUG3: Message received with 2 hops left, plus ACK will take 3 to deliver, delaying next transmit by 1050 milliseconds to avoid collisions.
03/18/2014 12:45:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/18/2014 12:45:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/18/2014 12:45:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 362/watts Accumulated Usage: 51.78/kWh Hops left: 2
03/18/2014 12:45:00  iMeter power has changed:362W, 51.78kWh
03/18/2014 12:46:00  Reading iMeter (scheduled)
03/18/2014 12:46:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/18/2014 12:46:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/18/2014 12:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/18/2014 12:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/18/2014 12:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
        PLM Response: (06) ACK

03/18/2014 12:46:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/18/2014 12:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/18/2014 12:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/18/2014 12:46:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/18/2014 12:46:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/18/2014 12:46:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1111111111
03/18/2014 12:46:00  [Insteon::iMeter] ACK Received for $miner_power3
03/18/2014 12:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200025b01050290017b00029ab22090
03/18/2014 12:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0251) insteon_ext_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 1b
                Message Type: (000) Direct Message
              Message Length: (1) Extended Length
                   Hops Left: 2
                    Max Hops: 3
         Insteon Message: 8200025b01050290017b00029ab22090
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 025b01050290017b00029ab22090

03/18/2014 12:46:00  [Insteon::BaseInterface] DEBUG3: Message received with 2 hops left, plus ACK will take 3 to deliver, delaying next transmit by 1050 milliseconds to avoid collisions.
03/18/2014 12:46:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/18/2014 12:46:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/18/2014 12:46:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 379/watts Accumulated Usage: 51.78/kWh Hops left: 2
03/18/2014 12:46:00  iMeter power has changed:379W, 51.78kWh
03/18/2014 12:47:00  Reading iMeter (scheduled)
03/18/2014 12:47:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/18/2014 12:47:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/18/2014 12:47:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/18/2014 12:47:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/18/2014 12:47:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
        PLM Response: (06) ACK

03/18/2014 12:47:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/18/2014 12:47:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/18/2014 12:47:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/18/2014 12:47:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/18/2014 12:47:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/18/2014 12:47:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1111111111
03/18/2014 12:47:00  [Insteon::iMeter] ACK Received for $miner_power3
03/18/2014 12:47:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b82000258010502
03/18/2014 12:47:00  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 02511988761486251b8200
03/18/2014 12:47:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0258) all_link_clean_status
         Status Byte: (01) NACK

03/18/2014 12:47:00  [Insteon_PLM] Received all-link cleanup success: obj=$miner_power3; command=imeter_query; extra=00
03/18/2014 12:47:00  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 0502
03/18/2014 12:47:00  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02511988761486251b82000502
03/18/2014 12:47:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200050280016a00029ac6e325
03/18/2014 12:47:00  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 02511988761486251b8200050280016a00029ac6e325
03/18/2014 12:48:00  Reading iMeter (scheduled)
03/18/2014 12:49:00  Reading iMeter (scheduled)
03/18/2014 12:50:00  Reading iMeter (scheduled)
03/18/2014 12:51:00  Reading iMeter (scheduled)
03/18/2014 12:52:00  Reading iMeter (scheduled)
03/18/2014 12:53:00  Reading iMeter (scheduled)
03/18/2014 12:54:00  Reading iMeter (scheduled)
03/18/2014 12:55:00  Reading iMeter (scheduled)
03/18/2014 12:55:00  Running: Weatherbug getforecast
03/18/2014 12:56:00  Reading iMeter (scheduled)
03/18/2014 12:57:00  Reading iMeter (scheduled)
03/18/2014 12:58:00  Reading iMeter (scheduled)
03/18/2014 12:59:00  Reading iMeter (scheduled)
03/18/2014 13:00:00  Reading iMeter (scheduled)
03/18/2014 13:00:00  FUNCTION: set_volume_pre_hook
03/18/2014 13:00:00  Setting speakers ON
03/18/2014 13:01:00  Reading iMeter (scheduled)
03/18/2014 13:02:00  Reading iMeter (scheduled)
03/18/2014 13:03:00  Reading iMeter (scheduled)
03/18/2014 13:03:13  Running: Read iMeter
03/18/2014 13:03:13  Reading iMeter
03/18/2014 13:03:39  Running: miner power3 status
03/18/2014 13:04:00  Reading iMeter (scheduled)
03/18/2014 13:04:07  Running: miner power3 scan link table
03/18/2014 13:04:07  [Insteon::ALDB_i2] $miner_power3 reading ALDB at location: 0x0000
03/18/2014 13:04:31  [Insteon_PLM] DEBUG2: Sending obj=$water_pump1; command=on; extra=FF incurred delay of 0.00 seconds; starting hop-count: 0
03/18/2014 13:04:31  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 026213ffd20011ff
03/18/2014 13:04:31  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 13:ff:d2
           Message Flags: 00
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 11ff
                       Cmd 1: (11) Light ON
                       Cmd 2: (ff) Level

03/18/2014 13:04:31  [Insteon::BaseObject] $water_pump1::set(on, web [192.168.69.1])
03/18/2014 13:04:31  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02511988761486251b8200050280016a00029ac6e325
03/18/2014 13:04:31  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200050280016a00029ac6e325026213ffd20011ff06
03/18/2014 13:04:31  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 13:ff:d2
           Message Flags: 00
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 11ff
                       Cmd 1: (11) Light ON
                       Cmd 2: (ff) Level
        PLM Response: (06) ACK

03/18/2014 13:04:31  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$water_pump1; command=on; extra=FF
03/18/2014 13:04:31  [Insteon_PLM] DEBUG3: Received PLM raw data: 025013ffd21486252011ff
03/18/2014 13:04:31  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 13:ff:d2
              To Address: 14:86:25
           Message Flags: 20
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 11ff
                       Cmd 1: (11) Light ON
                       Cmd 2: (ff) Level

03/18/2014 13:04:31  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:on; type:direct; group:
03/18/2014 13:04:31  [Insteon::BaseObject] DEBUG3: Adding hop count of 0 to hop_array of $water_pump1
03/18/2014 13:04:31  [Insteon::BaseObject] DEBUG4: $water_pump1->default_hop_count()=0 :: hop_array[]=0000
03/18/2014 13:04:31  [Insteon::BaseObject] received command/state acknowledge from $water_pump1: on and data: ff
03/18/2014 13:04:38  [Insteon_PLM] DEBUG2: Sending obj=$water_pump1; command=off; extra=00 incurred delay of 0.00 seconds; starting hop-count: 0
03/18/2014 13:04:38  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 026213ffd2001300
03/18/2014 13:04:38  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 13:ff:d2
           Message Flags: 00
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 1300
                       Cmd 1: (13) Light OFF
                       Cmd 2: 00

03/18/2014 13:04:38  [Insteon::BaseObject] $water_pump1::set(off, web [192.168.69.1])
03/18/2014 13:04:38  [Insteon_PLM] DEBUG3: Received PLM raw data: 026213ffd200130006
03/18/2014 13:04:38  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 13:ff:d2
           Message Flags: 00
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 1300
                       Cmd 1: (13) Light OFF
                       Cmd 2: 00
        PLM Response: (06) ACK

03/18/2014 13:04:38  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$water_pump1; command=off; extra=00
03/18/2014 13:04:38  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250
03/18/2014 13:04:38  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 0250
03/18/2014 13:04:38  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 0250
03/18/2014 13:04:38  [Insteon_PLM] DEBUG3: Received PLM raw data: 025013ffd2148625201300
03/18/2014 13:04:38  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 13:ff:d2
              To Address: 14:86:25
           Message Flags: 20
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 1300
                       Cmd 1: (13) Light OFF
                       Cmd 2: 00

03/18/2014 13:04:38  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:off; type:direct; group:
03/18/2014 13:04:38  [Insteon::BaseObject] DEBUG3: Adding hop count of 0 to hop_array of $water_pump1
03/18/2014 13:04:38  [Insteon::BaseObject] DEBUG4: $water_pump1->default_hop_count()=0 :: hop_array[]=00000
03/18/2014 13:04:38  [Insteon::BaseObject] received command/state acknowledge from $water_pump1: off and data: 00
03/18/2014 13:05:00  Reading iMeter (scheduled)
03/18/2014 13:05:00  Running: Weatherbug LiveWeather
03/18/2014 13:05:00  Weatherbug location liveweather.
03/18/2014 13:05:18  Running: Read iMeter
03/18/2014 13:05:18  Reading iMeter

After noticing the issue, I sent power on and off commands to $water_pump1 which works as expected. It did not 'reset' whatever issue was happening with reading the imeter.

@krkeegan
Copy link
Collaborator Author

Wow, @rudybrian it looks like you found a bug in a very low level routine in the Insteon stack.

From a quick glance, it appears that the portion of the code that parses out messages received from the PLM has incorrectly parsed a message from inside another message.

The Extended Received Msg should be 84 characters long. Only a portion of that message arrives during this loop (not uncommon for these long extended messages). The code recognizes that this is not a complete message. But then it bizarrely tries to process the message and finds a short 025801 message buried inside (the all link cleanup). Processing this causes all sorts of problems.

The solution is to fix the parser. This is a bit scary though, the parser is not written how I would choose to do it and the logic is not always clear to me. I would feel much more comfortable just rewriting it, but this will take time.

I will look later and see if I can figure out a quick solution to your issue. I suspect the 025801 characters are always present in the status responses from your iMeter. As a result, if an extended message is not fully delivered in a single loop (which is not uncommon) this will likely happen again.

Still doesn't explain the prior problem and may not explain all of your problems. Since you keep finding nifty things, I selfishly wouldn't mind if you kept testing things out.

@rudybrian
Copy link
Contributor

Glad this was helpful @krkeegan!

I'll happily keep testing and will report what I find.

@rudybrian
Copy link
Contributor

FYI: I ran three separate test runs today and after varying amounts of time all eventually resulted in the same parsing of the incomplete extended message as was observed yesterday.

@rudybrian
Copy link
Contributor

I ran another batch of tests which all but one ultimately resulted in the parsing of the incomplete extended message and subsequent ignoring of requested updates as was seen before.

The one exception occurred when I started a test (by restarting MH) just before the end of the minute, causing my user code to fire at the start of a new minute while the Insteon devices were still syncing with the PLM/MH. This also resulted in MH ignoring requests that should have been sent to the iMeter:

03/20/2014 10:45:58  ---------- Restart ----------
03/20/2014 10:45:58  [Insteon_PLM] serial:/dev/PLM:19200
03/20/2014 10:45:58  Reading /home/brudy/projects/misterhouse/mrhouse/local/mh.private.ini and mh.ini
03/20/2014 10:45:58  Reading 1 .mht table files: sets_devices.mht
03/20/2014 10:45:58  Translating sets_devices.mht -> ./../../local/code/sets_devices.mhp
03/20/2014 10:45:58  Initialized read_table_A.pl
03/20/2014 10:45:58  Reading 26 code files
03/20/2014 10:45:58  Evaluating user code
03/20/2014 10:45:58  [Insteon] Setting up initialization hooks
03/20/2014 10:45:58  [Insteon_PLM] setting default xmit delay to: 0.25
03/20/2014 10:45:58  [Insteon_PLM] setting x10 xmit delay to: 0.5
03/20/2014 10:45:58  running: aplay ./../sounds/sound_click1.wav

03/20/2014 10:45:58  [Insteon] DEBUG4 Checking aldb version of all devices
03/20/2014 10:45:58  [Insteon] DEBUG4 Checking aldb version for $water_pump1 (1 of 2)
03/20/2014 10:45:58  [Insteon::BaseDevice] DEBUG4: aldb_version is I1 but device is I2.  Remapping aldb version to I2
03/20/2014 10:45:58  [Insteon] DEBUG4 Checking aldb version for $miner_power3 (2 of 2)
03/20/2014 10:45:58  [Insteon::BaseDevice] DEBUG4: aldb_version is I1 but device is I2.  Remapping aldb version to I2
03/20/2014 10:45:58  [Insteon] DEBUG4 Checking aldb version of all devices completed
03/20/2014 10:45:58  [Insteon_PLM] DEBUG2: Sending obj=$PLM; interface_data= incurred delay of 0.00 seconds; starting hop-count: ?
03/20/2014 10:45:58  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0260
03/20/2014 10:45:58  [Insteon_PLM] DEBUG4:
         PLM Command: (0260) plm_info

03/20/2014 10:45:58  [Insteon] DEBUG4 Initializing thermostat versions
03/20/2014 10:45:58  Generating Voice commands for all Insteon objects
03/20/2014 10:45:59  [Insteon_PLM] DEBUG3: Received PLM raw data: 026014862503
03/20/2014 10:45:59  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 026014862503
03/20/2014 10:45:59  Rereading .menu code files.
03/20/2014 10:45:59  Organizer: Calendar matches target schema and does not require upgrading
03/20/2014 10:45:59  Organizer: Todo matches target schema and does not require upgrading
03/20/2014 10:45:59  Organizer: Reading updated organizer calendar file now
03/20/2014 10:45:59  Evaluating code organizer_events
03/20/2014 10:45:59  Organizer: Reading updated organizer todo file
03/20/2014 10:45:59  Evaluating code organizer_tasks
03/20/2014 10:45:59  Running: Weatherbug LiveWeather
03/20/2014 10:45:59  Running: Weatherbug getforecast
03/20/2014 10:45:59  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 026014862503
03/20/2014 10:45:59  [Insteon_PLM] DEBUG3: Received PLM raw data: 026014862503159206
03/20/2014 10:45:59  [Insteon_PLM] DEBUG4:
         PLM Command: (0260) plm_info
       PLM Device ID: 14:86:25
     Device Category: 03:15
            Firmware: 92
        PLM Response: (06) ACK

03/20/2014 10:45:59  [Insteon_PLM] PLM id: 148625 firmware: 92
03/20/2014 10:45:59  [Insteon_PLM] DEBUG2: Sending obj=$water_pump1; command=get_engine_version incurred delay of 0.25 seconds; starting hop-count: 0
03/20/2014 10:45:59  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 026213ffd2000d00
03/20/2014 10:45:59  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 13:ff:d2
           Message Flags: 00
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 0d00
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: 00

03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026213ffd2000d0006
03/20/2014 10:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 13:ff:d2
           Message Flags: 00
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 0d00
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: 00
        PLM Response: (06) ACK

03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$water_pump1; command=get_engine_version
03/20/2014 10:46:00  Reading iMeter (scheduled)
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 025013ffd2148625200d01
03/20/2014 10:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 13:ff:d2
              To Address: 14:86:25
           Message Flags: 20
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 0d01
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: (01) i2

03/20/2014 10:46:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:get_engine_version; type:direct; group:
03/20/2014 10:46:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 0 to hop_array of $water_pump1
03/20/2014 10:46:00  [Insteon::BaseObject] DEBUG4: $water_pump1->default_hop_count()=0 :: hop_array[]=00
03/20/2014 10:46:00  [Insteon::BaseObject] received engine version for $water_pump1 of I2. hops left: 0
03/20/2014 10:46:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=get_engine_version incurred delay of 0.57 seconds; starting hop-count: 1
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876050d00
03/20/2014 10:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 0d00
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: 00

03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0262198876050d0006
03/20/2014 10:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 0d00
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: 00
        PLM Response: (06) ACK

03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=get_engine_version
03/20/2014 10:46:00  Weatherbug location liveweather.
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 0250198876
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 0250198876
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625210d01
03/20/2014 10:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 0d01
                       Cmd 1: (0d) Get INSTEON Engine Version
                       Cmd 2: (01) i2

03/20/2014 10:46:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:get_engine_version; type:direct; group:
03/20/2014 10:46:00  [Insteon::BaseObject] received engine version for $miner_power3 of I2. hops left: 0
03/20/2014 10:46:00  [Insteon_PLM] DEBUG2: Sending obj=$water_pump1; command=status_request incurred delay of 0.93 seconds; starting hop-count: 0
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 026213ffd2001900
03/20/2014 10:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 13:ff:d2
           Message Flags: 00
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 1900
                       Cmd 1: (19) Light Status Request
                       Cmd 2: (00) On Level

03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026213ffd200190006
03/20/2014 10:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 13:ff:d2
           Message Flags: 00
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 1900
                       Cmd 1: (19) Light Status Request
                       Cmd 2: (00) On Level
        PLM Response: (06) ACK

03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$water_pump1; command=status_request
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 025013ffd2148625200000
03/20/2014 10:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 13:ff:d2
              To Address: 14:86:25
           Message Flags: 20
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 0
         Insteon Message: 0000
                       Cmd 1: 00 Insteon command not decoded
                       Cmd 2: 00

03/20/2014 10:46:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:; type:direct; group:
03/20/2014 10:46:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 0 to hop_array of $water_pump1
03/20/2014 10:46:00  [Insteon::BaseObject] DEBUG4: $water_pump1->default_hop_count()=0 :: hop_array[]=000
03/20/2014 10:46:00  [Insteon::BaseObject] received status for $water_pump1 with on-level: 0%, hops left: 0
03/20/2014 10:46:00  [Insteon::BaseObject] $water_pump1::set_receive(off, $PLM)
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b88000220
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 02511988761486251b88000220
03/20/2014 10:46:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 1.19 seconds; starting hop-count: 1
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/20/2014 10:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02511988761486251b88000220
03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b880002208ca200000000000000000000026219887605820006
03/20/2014 10:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 19:88:76
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
        PLM Response: (06) ACK

03/20/2014 10:46:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/20/2014 10:46:00  [Insteon_PLM] DEBUG4:
         PLM Command: (0251) insteon_ext_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 1b
                Message Type: (000) Direct Message
              Message Length: (1) Extended Length
                   Hops Left: 2
                    Max Hops: 3
         Insteon Message: 880002208ca200000000000000000000
                       Cmd 1: 88 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 02208ca200000000000000000000

03/20/2014 10:46:00  [Insteon::BaseInterface] DEBUG3: Message received with 2 hops left, plus ACK will take 3 to deliver, delaying next transmit by 1050 milliseconds to avoid collisions.
03/20/2014 10:46:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:; type:direct; group:
03/20/2014 10:46:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/20/2014 10:46:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/20/2014 10:46:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=11
03/20/2014 10:46:00  [Insteon::BaseObject] Ignoring unsupported command from $miner_power3
03/20/2014 10:46:01  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/20/2014 10:46:01  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 21
                Message Type: (001) ACK of Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 0
                    Max Hops: 1
         Insteon Message: 8200
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00

03/20/2014 10:46:01  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/20/2014 10:46:01  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/20/2014 10:46:01  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=111
03/20/2014 10:46:01  [Insteon::iMeter] ACK Received for $miner_power3
03/20/2014 10:46:01  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200031e0104029001ed00039955
03/20/2014 10:46:01  [Insteon_PLM] DEBUG3: Saving parsed data fragment: 02511988761486251b8200031e0104029001ed00039955
03/20/2014 10:46:02  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02511988761486251b8200031e0104029001ed00039955
03/20/2014 10:46:02  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200031e0104029001ed00039955e75a
03/20/2014 10:46:02  [Insteon_PLM] DEBUG4:
         PLM Command: (0251) insteon_ext_received
            From Address: 19:88:76
              To Address: 14:86:25
           Message Flags: 1b
                Message Type: (000) Direct Message
              Message Length: (1) Extended Length
                   Hops Left: 2
                    Max Hops: 3
         Insteon Message: 8200031e0104029001ed00039955e75a
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 031e0104029001ed00039955e75a

03/20/2014 10:46:02  [Insteon::BaseInterface] DEBUG3: Message received with 2 hops left, plus ACK will take 3 to deliver, delaying next transmit by 1050 milliseconds to avoid collisions.
03/20/2014 10:46:02  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/20/2014 10:46:02  [Insteon::BaseInterface] Processing message for $miner_power3
03/20/2014 10:46:02  [Insteon::iMeter] received status for $miner_power3. Current Usage: 493/watts Accumulated Usage: 71.56/kWh Hops left: 2
03/20/2014 10:46:02  [Insteon::BaseInterface] Attempt to queue command already in queue; skipping ...
03/20/2014 10:46:02  iMeter power has changed:493W, 71.56kWh
03/20/2014 10:47:00  Reading iMeter (scheduled)
03/20/2014 10:48:00  Reading iMeter (scheduled)
03/20/2014 10:49:00  Reading iMeter (scheduled)

krkeegan added a commit to krkeegan/misterhouse that referenced this pull request Mar 25, 2014
Changes the PLM parser to a First-In-First-Out style.  This should resolve the issue found in hollie#374 where shorter messages were being excerpted out of the middle of larger messages.

I believe the routine is significantly easier to read.

Removed the use of the split routine which created really odd results, and was not the most logical code to follow.

This also likely solves other latent issues that may not have been apparent.
@krkeegan
Copy link
Collaborator Author

The code in this pull request seems to be working.

I am going to merge this and submit a new pull request to try and resolve the parser errors that @rudybrian is getting.

krkeegan added a commit that referenced this pull request Mar 25, 2014
Add Support for Insteon iMeter Solo and SynchroLinc
@krkeegan krkeegan merged commit 55554ea into hollie:master Mar 25, 2014
@krkeegan krkeegan deleted the insteon_energy branch June 13, 2014 23:56
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants