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

Completely Rewritten Insteon Message Parser #388

Merged
merged 7 commits into from
Apr 15, 2014

Conversation

krkeegan
Copy link
Collaborator

This code changes the PLM parser to a First-In-First-Out type of parser. This should resolve the issue found in #374 where shorter messages were being excerpted out of the middle of larger messages.

This path fixes a number of notable problems with the prior code:

  • The routine is significantly easier to read now.
  • The use of the split to break out multiple messages has been removed. Using split created really odd results, such as blank messages, out of order messages, and the problem noted above. Moreover, it was not the most logical code to follow.
  • This also likely solves other latent issues that may not have been apparent, but were caused by the oddities of the old parser.

@rudybrian, since you seem to be most able to reproduce a parser error, can you test this out and see if this solved that issue?

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 krkeegan changed the title Completely ReWritten _parse_data Routine Completely Rewritten Insteon Message Parser Mar 25, 2014
@rudybrian
Copy link
Contributor

@krkeegan, will do. Looks good a first blush, but will give it some time.

@rudybrian
Copy link
Contributor

I was doing some experiments that required restarting MH multiple times and managed to induce a failure when my user code fired at the top of the minute at 13:07:00 while the Insteon devices were still synching with MH:

03/26/2014 13:06:56  [Insteon_PLM] serial:/dev/PLM:19200
03/26/2014 13:06:56  Perl @INC contains: ./../../local/code, ./../code/common, /home/brudy/projects/misterhouse/mrhouse/misterhouse/bin/../lib, /home/brudy/projects/misterhouse/mrhouse/misterhouse/bin/../lib/site, ., /usr/local/lib64/perl5, /usr/local/share/perl5, /usr/lib64/perl5/vendor_perl, /usr/share/perl5/vendor_perl, /usr/lib64/perl5, /usr/share/perl5, .
03/26/2014 13:06:56  Reading /home/brudy/projects/misterhouse/mrhouse/local/mh.private.ini and mh.ini
03/26/2014 13:06:56  Reading 1 .mht table files: sets_devices.mht
03/26/2014 13:06:56  Translating sets_devices.mht -> ./../../local/code/sets_devices.mhp
03/26/2014 13:06:56  Initialized read_table_A.pl
03/26/2014 13:06:56  Reading 26 code files
03/26/2014 13:06:56  Evaluating user code
03/26/2014 13:06:56  [Insteon_PLM] 2412[US] using serial,  serial_port=/dev/PLM
03/26/2014 13:06:56  [Insteon] Setting up initialization hooks
03/26/2014 13:06:56  [Insteon_PLM] setting default xmit delay to: 0.25
03/26/2014 13:06:56  [Insteon_PLM] setting x10 xmit delay to: 0.5
03/26/2014 13:06:56  [Pushover] Pushover object initialized
03/26/2014 13:06:56  running: aplay ./../sounds/sound_click1.wav

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

03/26/2014 13:06:56  [Insteon] DEBUG4 Initializing thermostat versions
03/26/2014 13:06:56  Generating Voice commands for all Insteon objects
03/26/2014 13:06:56  Rereading .menu code files.
03/26/2014 13:06:56  Organizer: Calendar matches target schema and does not require upgrading
03/26/2014 13:06:56  Organizer: Todo matches target schema and does not require upgrading
03/26/2014 13:06:56  Organizer: Reading updated organizer calendar file now
03/26/2014 13:06:56  Evaluating code organizer_events
03/26/2014 13:06:56  Organizer: Reading updated organizer todo file
03/26/2014 13:06:56  Evaluating code organizer_tasks
03/26/2014 13:06:56  Running: Weatherbug LiveWeather
03/26/2014 13:06:56  Running: Weatherbug getforecast
03/26/2014 13:06:56  [Insteon_PLM] DEBUG3: Received PLM raw data: 026014862503159206
03/26/2014 13:06:56  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026014862503159206
03/26/2014 13:06:56  [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/26/2014 13:06:56  [Insteon_PLM] PLM id: 026014 firmware: 03
03/26/2014 13:06:57  [Insteon_PLM] DEBUG2: Sending obj=$water_pump1; command=get_engine_version incurred delay of 0.26 seconds; starting hop-count: 0
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 026213ffd2000d00
03/26/2014 13:06:57  [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/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Received PLM raw data: 026213ffd2000d0006025013ffd2148625200d01
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026213ffd2000d0006025013ffd2148625200d01
03/26/2014 13:06:57  [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/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$water_pump1; command=get_engine_version
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025013ffd2148625200d01
03/26/2014 13:06:57  [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/26/2014 13:06:57  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:get_engine_version; type:direct; group:
03/26/2014 13:06:57  [Insteon::BaseObject] DEBUG3: Adding hop count of 0 to hop_array of $water_pump1
03/26/2014 13:06:57  [Insteon::BaseObject] DEBUG4: $water_pump1->default_hop_count()=0 :: hop_array[]=00
03/26/2014 13:06:57  [Insteon::BaseObject] received engine version for $water_pump1 of I2. hops left: 0
03/26/2014 13:06:57  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=get_engine_version incurred delay of 0.49 seconds; starting hop-count: 1
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876050d00
03/26/2014 13:06:57  [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/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Received PLM raw data: 0262198876050d0006
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0262198876050d0006
03/26/2014 13:06:57  [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/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=get_engine_version
03/26/2014 13:06:57  Weatherbug location liveweather.
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625210d01
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625210d01
03/26/2014 13:06:57  [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/26/2014 13:06:57  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:get_engine_version; type:direct; group:
03/26/2014 13:06:57  [Insteon::BaseObject] received engine version for $miner_power3 of I2. hops left: 0
03/26/2014 13:06:57  [Insteon_PLM] DEBUG2: Sending obj=$water_pump1; command=status_request incurred delay of 0.76 seconds; starting hop-count: 0
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 026213ffd2001900
03/26/2014 13:06:57  [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/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Received PLM raw data: 026213ffd200190006
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026213ffd200190006
03/26/2014 13:06:57  [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/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$water_pump1; command=status_request
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Received PLM raw data: 025013ff
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025013ff
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Saving data fragment: 025013ff
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Received PLM raw data: d2148625200000
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 025013ff
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025013ffd2148625200000
03/26/2014 13:06:57  [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/26/2014 13:06:57  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:; type:direct; group:
03/26/2014 13:06:57  [Insteon::BaseObject] DEBUG3: Adding hop count of 0 to hop_array of $water_pump1
03/26/2014 13:06:57  [Insteon::BaseObject] DEBUG4: $water_pump1->default_hop_count()=0 :: hop_array[]=000
03/26/2014 13:06:57  [Insteon::BaseObject] received status for $water_pump1 with on-level: 0%, hops left: 0
03/26/2014 13:06:57  [Insteon::BaseObject] $water_pump1::set_receive(off, $PLM)
03/26/2014 13:06:57  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 1.02 seconds; starting hop-count: 1
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/26/2014 13:06:57  [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/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
03/26/2014 13:06:57  [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/26/2014 13:06:57  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/26/2014 13:06:58  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/26/2014 13:06:58  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
03/26/2014 13:06:58  [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/26/2014 13:06:58  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/26/2014 13:06:58  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/26/2014 13:06:58  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=11
03/26/2014 13:06:58  [Insteon::iMeter] ACK Received for $miner_power3
03/26/2014 13:06:58  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b88000402e6c200000000000000000000
03/26/2014 13:06:58  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b88000402e6c200000000000000000000
03/26/2014 13:06:58  [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: 88000402e6c200000000000000000000
                       Cmd 1: 88 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 0402e6c200000000000000000000

03/26/2014 13:06:58  [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/26/2014 13:06:58  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:; type:direct; group:
03/26/2014 13:06:58  [Insteon::BaseInterface] Processing message for $miner_power3
03/26/2014 13:06:58  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/26/2014 13:06:58  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=111
03/26/2014 13:06:58  [Insteon::BaseObject] Ignoring unsupported command from $miner_power3
03/26/2014 13:06:59  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 1 attempts.
03/26/2014 13:06:59  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
03/26/2014 13:06:59  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=2111
03/26/2014 13:06:59  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 2.79 seconds; starting hop-count: 1
03/26/2014 13:06:59  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/26/2014 13:06:59  [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/26/2014 13:06:59  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/26/2014 13:06:59  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
03/26/2014 13:06:59  [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/26/2014 13:06:59  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/26/2014 13:06:59  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/26/2014 13:06:59  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
03/26/2014 13:06:59  [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/26/2014 13:06:59  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/26/2014 13:06:59  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/26/2014 13:06:59  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=12111
03/26/2014 13:06:59  [Insteon::iMeter] ACK Received for $miner_power3
03/26/2014 13:07:00  Reading iMeter (scheduled)
03/26/2014 13:07:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200025d01060290017a0006c5ae561f
03/26/2014 13:07:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200025d01060290017a0006c5ae561f
03/26/2014 13:07: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: 8200025d01060290017a0006c5ae561f
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 025d01060290017a0006c5ae561f

03/26/2014 13:07: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/26/2014 13:07:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/26/2014 13:07:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/26/2014 13:07:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 378/watts Accumulated Usage: 134.66/kWh Hops left: 2
03/26/2014 13:07:00  [Insteon::BaseInterface] Attempt to queue command already in queue; skipping ...
03/26/2014 13:07:00  iMeter power has changed:378W, 134.66kWh
03/26/2014 13:07:01  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/26/2014 13:07:16  Running: Send pushover notification to tusdroidrazrhd
03/26/2014 13:07:16  Sending Pushover notification to tusdroidrazrhd
03/26/2014 13:07:16  [Pushover] message: A low priority test message to tusdroidrazrhd
03/26/2014 13:08:00  Reading iMeter (scheduled)
03/26/2014 13:09:00  Reading iMeter (scheduled)
03/26/2014 13:10:00  Reading iMeter (scheduled)
03/26/2014 13:10:00  Livingroom temperature: 90.20 F
03/26/2014 13:11:00  Reading iMeter (scheduled)
03/26/2014 13:11:21  Running: Read iMeter
03/26/2014 13:11:21  Reading iMeter
03/26/2014 13:11:45  Running: miner power3 get engine version
03/26/2014 13:12:00  Reading iMeter (scheduled)
03/26/2014 13:12:18  Running: miner power3 scan link table
03/26/2014 13:12:18  [Insteon::ALDB_i2] $miner_power3 reading ALDB at location: 0x0000
03/26/2014 13:12:31  Running: water pump1 status
03/26/2014 13:12:31  [Insteon_PLM] DEBUG2: Sending obj=$water_pump1; command=status_request incurred delay of 0.00 seconds; starting hop-count: 0
03/26/2014 13:12:31  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 026213ffd2001900
03/26/2014 13:12: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: 1900
                       Cmd 1: (19) Light Status Request
                       Cmd 2: (00) On Level

03/26/2014 13:12:31  [Insteon_PLM] DEBUG3: Received PLM raw data: 026213ffd200190006
03/26/2014 13:12:31  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026213ffd200190006
03/26/2014 13:12: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: 1900
                       Cmd 1: (19) Light Status Request
                       Cmd 2: (00) On Level
        PLM Response: (06) ACK

03/26/2014 13:12:31  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$water_pump1; command=status_request
03/26/2014 13:12:31  [Insteon_PLM] DEBUG3: Received PLM raw data: 025013ffd2148625200000
03/26/2014 13:12:31  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025013ffd2148625200000
03/26/2014 13:12: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: 0000
                       Cmd 1: 00 Insteon command not decoded
                       Cmd 2: 00

03/26/2014 13:12:31  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:; type:direct; group:
03/26/2014 13:12:31  [Insteon::BaseObject] DEBUG3: Adding hop count of 0 to hop_array of $water_pump1
03/26/2014 13:12:31  [Insteon::BaseObject] DEBUG4: $water_pump1->default_hop_count()=0 :: hop_array[]=0000
03/26/2014 13:12:31  [Insteon::BaseObject] received status for $water_pump1 with on-level: 0%, hops left: 0
03/26/2014 13:12:31  [Insteon::BaseObject] $water_pump1::set_receive(off, $PLM)
03/26/2014 13:12:38  Running: water pump1 on
03/26/2014 13:12:38  [Insteon_PLM] DEBUG2: Sending obj=$water_pump1; command=on; extra=FF incurred delay of 0.00 seconds; starting hop-count: 0
03/26/2014 13:12:38  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 026213ffd20011ff
03/26/2014 13:12: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: 11ff
                       Cmd 1: (11) Light ON
                       Cmd 2: (ff) Level

03/26/2014 13:12:38  [Insteon::BaseObject] $water_pump1::set(on, )
03/26/2014 13:12:38  [Insteon_PLM] DEBUG3: Received PLM raw data: 026213ffd20011ff06
03/26/2014 13:12:38  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026213ffd20011ff06
03/26/2014 13:12: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: 11ff
                       Cmd 1: (11) Light ON
                       Cmd 2: (ff) Level
        PLM Response: (06) ACK

03/26/2014 13:12:38  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$water_pump1; command=on; extra=FF
03/26/2014 13:12:38  [Insteon_PLM] DEBUG3: Received PLM raw data: 025013ffd21486252011ff
03/26/2014 13:12:38  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025013ffd21486252011ff
03/26/2014 13:12: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: 11ff
                       Cmd 1: (11) Light ON
                       Cmd 2: (ff) Level

03/26/2014 13:12:38  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:on; type:direct; group:
03/26/2014 13:12:38  [Insteon::BaseObject] DEBUG3: Adding hop count of 0 to hop_array of $water_pump1
03/26/2014 13:12:38  [Insteon::BaseObject] DEBUG4: $water_pump1->default_hop_count()=0 :: hop_array[]=00000
03/26/2014 13:12:38  [Insteon::BaseObject] received command/state acknowledge from $water_pump1: on and data: ff
03/26/2014 13:12:44  Running: water pump1 off
03/26/2014 13:12:44  [Insteon_PLM] DEBUG2: Sending obj=$water_pump1; command=off; extra=00 incurred delay of 0.00 seconds; starting hop-count: 0
03/26/2014 13:12:44  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 026213ffd2001300
03/26/2014 13:12:44  [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/26/2014 13:12:44  [Insteon::BaseObject] $water_pump1::set(off, )
03/26/2014 13:12:44  [Insteon_PLM] DEBUG3: Received PLM raw data: 026213ffd200130006
03/26/2014 13:12:44  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026213ffd200130006
03/26/2014 13:12:44  [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/26/2014 13:12:44  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$water_pump1; command=off; extra=00
03/26/2014 13:12:44  [Insteon_PLM] DEBUG3: Received PLM raw data: 025013ff
03/26/2014 13:12:44  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025013ff
03/26/2014 13:12:44  [Insteon_PLM] DEBUG3: Saving data fragment: 025013ff
03/26/2014 13:12:44  [Insteon_PLM] DEBUG3: Received PLM raw data: d2148625201300
03/26/2014 13:12:44  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 025013ff
03/26/2014 13:12:44  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025013ffd2148625201300
03/26/2014 13:12:44  [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/26/2014 13:12:44  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:off; type:direct; group:
03/26/2014 13:12:44  [Insteon::BaseObject] DEBUG3: Adding hop count of 0 to hop_array of $water_pump1
03/26/2014 13:12:44  [Insteon::BaseObject] DEBUG4: $water_pump1->default_hop_count()=0 :: hop_array[]=000000
03/26/2014 13:12:44  [Insteon::BaseObject] received command/state acknowledge from $water_pump1: off and data: 00
03/26/2014 13:12:49  Running: miner power3 status
03/26/2014 13:13:00  Reading iMeter (scheduled)

@krkeegan
Copy link
Collaborator Author

I believe the problem happens because of:

03/26/2014 13:07:00 [Insteon::BaseInterface] Attempt to queue command already in queue; skipping ...

This has been an ongoing nagging issue. While "skipping" the message sounds benign, it has dramatic consequences because neither the success nor failure_callbacks are called for this message. As a result, the message queue for this device gets stuck in a state where it is waiting for something to happen that never does.

I have been looking into patches to solve this such as calling the success or failure callbacks when skipping a message. But each of these patches would potentially cause ripple effects that are hard to anticipate.

Currently, I am thinking that the best solution is to no longer skip duplicate messages. They rarely happen, and when they do they are most likely intentional. I will keep the warning in the log, but allow the duplicate message to be processed. This should solve this issue and hopefully we won't get stuck in some infinite loop.

@krkeegan
Copy link
Collaborator Author

OK, hopefully that most recent commit should do it.

@rudybrian
Copy link
Contributor

Hi @krkeegan, that seems to have done it.

03/27/2014 15:36:57  [Insteon_PLM] serial:/dev/PLM:19200
03/27/2014 15:36:57  Perl @INC contains: ./../../local/code, ./../code/common, /home/brudy/projects/misterhouse/mrhouse/misterhouse/bin/../lib, /home/brudy/projects/misterhouse/mrhouse/misterhouse/bin/../lib/site, ., /usr/local/lib64/perl5, /usr/local/share/perl5, /usr/lib64/perl5/vendor_perl, /usr/share/perl5/vendor_perl, /usr/lib64/perl5, /usr/share/perl5, .
03/27/2014 15:36:57  Reading /home/brudy/projects/misterhouse/mrhouse/local/mh.private.ini and mh.ini
03/27/2014 15:36:57  Reading 1 .mht table files: sets_devices.mht
03/27/2014 15:36:57  Translating sets_devices.mht -> ./../../local/code/sets_devices.mhp
03/27/2014 15:36:57  Initialized read_table_A.pl
03/27/2014 15:36:57  Reading 26 code files
03/27/2014 15:36:57  Evaluating user code
03/27/2014 15:36:57  [Insteon_PLM] 2412[US] using serial,  serial_port=/dev/PLM
03/27/2014 15:36:57  [Insteon] Setting up initialization hooks
03/27/2014 15:36:57  [Insteon_PLM] setting default xmit delay to: 0.25
03/27/2014 15:36:57  [Insteon_PLM] setting x10 xmit delay to: 0.5
03/27/2014 15:36:57  [Pushover] Pushover object initialized
03/27/2014 15:36:57  running: aplay ./../sounds/sound_click1.wav

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

03/27/2014 15:36:57  [Insteon] DEBUG4 Initializing thermostat versions
03/27/2014 15:36:57  Generating Voice commands for all Insteon objects
03/27/2014 15:36:58  Rereading .menu code files.
03/27/2014 15:36:58  Organizer: Calendar matches target schema and does not require upgrading
03/27/2014 15:36:58  Organizer: Todo matches target schema and does not require upgrading
03/27/2014 15:36:58  Organizer: Reading updated organizer calendar file now
03/27/2014 15:36:58  Evaluating code organizer_events
03/27/2014 15:36:58  Organizer: Reading updated organizer todo file
03/27/2014 15:36:58  Evaluating code organizer_tasks
03/27/2014 15:36:58  Running: Weatherbug LiveWeather
03/27/2014 15:36:58  Running: Weatherbug getforecast
03/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Received PLM raw data: 026014862503159206
03/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026014862503159206
03/27/2014 15:36:58  [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/27/2014 15:36:58  [Insteon_PLM] PLM id: 026014 firmware: 03
03/27/2014 15:36:58  [Insteon_PLM] DEBUG2: Sending obj=$water_pump1; command=get_engine_version incurred delay of 0.26 seconds; starting hop-count: 1
03/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 026213ffd2050d00
03/27/2014 15:36:58  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 13:ff:d2
           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/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Received PLM raw data: 026213ffd2050d0006
03/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026213ffd2050d0006
03/27/2014 15:36:58  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 13:ff:d2
           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/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$water_pump1; command=get_engine_version
03/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Received PLM raw data: 025013ffd21486
03/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025013ffd21486
03/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Saving data fragment: 025013ffd21486
03/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Received PLM raw data: 25210d01
03/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 025013ffd21486
03/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025013ffd2148625210d01
03/27/2014 15:36:58  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 13:ff:d2
              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/27/2014 15:36:58  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:get_engine_version; type:direct; group:
03/27/2014 15:36:58  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $water_pump1
03/27/2014 15:36:58  [Insteon::BaseObject] DEBUG4: $water_pump1->default_hop_count()=1 :: hop_array[]=11
03/27/2014 15:36:58  [Insteon::BaseObject] received engine version for $water_pump1 of I2. hops left: 0
03/27/2014 15:36:58  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=get_engine_version incurred delay of 0.57 seconds; starting hop-count: 1
03/27/2014 15:36:58  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876050d00
03/27/2014 15:36:58  [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/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Received PLM raw data: 0262198876050d0006
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0262198876050d0006
03/27/2014 15:36:59  [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/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=get_engine_version
03/27/2014 15:36:59  Weatherbug location liveweather.
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Received PLM raw data: 02501988
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02501988
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Saving data fragment: 02501988
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Received PLM raw data: 76148625210d01
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02501988
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625210d01
03/27/2014 15:36:59  [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/27/2014 15:36:59  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:get_engine_version; type:direct; group:
03/27/2014 15:36:59  [Insteon::BaseObject] received engine version for $miner_power3 of I2. hops left: 0
03/27/2014 15:36:59  [Insteon_PLM] DEBUG2: Sending obj=$water_pump1; command=status_request incurred delay of 0.91 seconds; starting hop-count: 1
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 026213ffd2051900
03/27/2014 15:36:59  [Insteon_PLM] DEBUG4:
         PLM Command: (0262) insteon_send
              To Address: 13:ff:d2
           Message Flags: 05
                Message Type: (000) Direct Message
              Message Length: (0) Standard Length
                   Hops Left: 1
                    Max Hops: 1
         Insteon Message: 1900
                       Cmd 1: (19) Light Status Request
                       Cmd 2: (00) On Level

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

03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$water_pump1; command=status_request
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Received PLM raw data: 025013ffd2148625
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025013ffd2148625
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Saving data fragment: 025013ffd2148625
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Received PLM raw data: 210000
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 025013ffd2148625
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025013ffd2148625210000
03/27/2014 15:36:59  [Insteon_PLM] DEBUG4:
         PLM Command: (0250) insteon_received
            From Address: 13:ff:d2
              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: 0000
                       Cmd 1: 00 Insteon command not decoded
                       Cmd 2: 00

03/27/2014 15:36:59  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:; type:direct; group:
03/27/2014 15:36:59  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $water_pump1
03/27/2014 15:36:59  [Insteon::BaseObject] DEBUG4: $water_pump1->default_hop_count()=1 :: hop_array[]=111
03/27/2014 15:36:59  [Insteon::BaseObject] received status for $water_pump1 with on-level: 0%, hops left: 0
03/27/2014 15:36:59  [Insteon::BaseObject] $water_pump1::set_receive(off, $PLM)
03/27/2014 15:36:59  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 1.22 seconds; starting hop-count: 1
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/27/2014 15:36:59  [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/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
03/27/2014 15:36:59  [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/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8800045a407600000000000000000000
03/27/2014 15:36:59  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8800045a407600000000000000000000
03/27/2014 15:36:59  [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: 8800045a407600000000000000000000
                       Cmd 1: 88 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 045a407600000000000000000000

03/27/2014 15:36:59  [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/27/2014 15:36:59  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:; type:direct; group:
03/27/2014 15:36:59  [Insteon::BaseInterface] Processing message for $miner_power3
03/27/2014 15:36:59  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/27/2014 15:36:59  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=11
03/27/2014 15:36:59  [Insteon::BaseObject] Ignoring unsupported command from $miner_power3
03/27/2014 15:37:00  Reading iMeter (scheduled)
03/27/2014 15:37:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/27/2014 15:37:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
03/27/2014 15:37: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/27/2014 15:37:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:37:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/27/2014 15:37:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=111
03/27/2014 15:37:00  [Insteon::iMeter] ACK Received for $miner_power3
03/27/2014 15:37:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200026801040280017300075639de3c
03/27/2014 15:37:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200026801040280017300075639de3c
03/27/2014 15:37: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: 8200026801040280017300075639de3c
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 026801040280017300075639de3c

03/27/2014 15:37: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/27/2014 15:37:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:37:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/27/2014 15:37:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 371/watts Accumulated Usage: 145.88/kWh Hops left: 2
03/27/2014 15:37:00  [Insteon::BaseInterface] WARN queuing a duplicate command already in queue.
03/27/2014 15:37:00  iMeter power has changed:371W, 145.88kWh
03/27/2014 15:37:01  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 1.78 seconds; starting hop-count: 1
03/27/2014 15:37:01  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/27/2014 15:37: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/27/2014 15:37:01  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/27/2014 15:37:01  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
03/27/2014 15:37: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
        PLM Response: (06) ACK

03/27/2014 15:37:01  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/27/2014 15:37:02  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/27/2014 15:37:02  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
03/27/2014 15:37:02  [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/27/2014 15:37:02  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:37:02  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/27/2014 15:37:02  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1111
03/27/2014 15:37:02  [Insteon::iMeter] ACK Received for $miner_power3
03/27/2014 15:37:02  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200026201040290016d0007563a9304
03/27/2014 15:37:02  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200026201040290016d0007563a9304
03/27/2014 15:37: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: 8200026201040290016d0007563a9304
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 026201040290016d0007563a9304

03/27/2014 15:37: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/27/2014 15:37:02  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:37:02  [Insteon::BaseInterface] Processing message for $miner_power3
03/27/2014 15:37:02  [Insteon::iMeter] received status for $miner_power3. Current Usage: 365/watts Accumulated Usage: 145.88/kWh Hops left: 2
03/27/2014 15:37:02  iMeter power has changed:365W, 145.88kWh
03/27/2014 15:37:49  Running: Read iMeter
03/27/2014 15:37:49  Reading iMeter
03/27/2014 15:37:49  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/27/2014 15:37:49  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/27/2014 15:37:49  [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/27/2014 15:37:49  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/27/2014 15:37:49  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
03/27/2014 15:37:49  [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/27/2014 15:37:49  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/27/2014 15:37:49  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/27/2014 15:37:49  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
03/27/2014 15:37:49  [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/27/2014 15:37:49  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:37:49  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/27/2014 15:37:49  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=11111
03/27/2014 15:37:49  [Insteon::iMeter] ACK Received for $miner_power3
03/27/2014 15:37:50  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200026001040290017e0007564ad25a
03/27/2014 15:37:50  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200026001040290017e0007564ad25a
03/27/2014 15:37:50  [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: 8200026001040290017e0007564ad25a
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 026001040290017e0007564ad25a

03/27/2014 15:37:50  [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/27/2014 15:37:50  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:37:50  [Insteon::BaseInterface] Processing message for $miner_power3
03/27/2014 15:37:50  [Insteon::iMeter] received status for $miner_power3. Current Usage: 382/watts Accumulated Usage: 145.89/kWh Hops left: 2
03/27/2014 15:37:50  iMeter power has changed:382W, 145.89kWh
03/27/2014 15:37:51  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/27/2014 15:38:00  Reading iMeter (scheduled)
03/27/2014 15:38:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/27/2014 15:38:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/27/2014 15:38: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/27/2014 15:38:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/27/2014 15:38:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
03/27/2014 15:38: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/27/2014 15:38:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/27/2014 15:38:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/27/2014 15:38:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
03/27/2014 15:38: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/27/2014 15:38:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:38:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/27/2014 15:38:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=111111
03/27/2014 15:38:00  [Insteon::iMeter] ACK Received for $miner_power3
03/27/2014 15:38:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200026101040290016c0007564dc745
03/27/2014 15:38:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200026101040290016c0007564dc745
03/27/2014 15:38: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: 8200026101040290016c0007564dc745
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 026101040290016c0007564dc745

03/27/2014 15:38: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/27/2014 15:38:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:38:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/27/2014 15:38:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 364/watts Accumulated Usage: 145.89/kWh Hops left: 2
03/27/2014 15:38:00  iMeter power has changed:364W, 145.89kWh
03/27/2014 15:39:00  Reading iMeter (scheduled)
03/27/2014 15:39:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/27/2014 15:39: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/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
03/27/2014 15:39: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/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
03/27/2014 15:39: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/27/2014 15:39:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:39:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/27/2014 15:39:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1111111
03/27/2014 15:39:00  [Insteon::iMeter] ACK Received for $miner_power3
03/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b820002620104028001
03/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b820002620104028001
03/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Saving data fragment: 02511988761486251b820002620104028001
03/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 6700075661e557
03/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02511988761486251b820002620104028001
03/27/2014 15:39:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200026201040280016700075661e557
03/27/2014 15:39: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: 8200026201040280016700075661e557
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 026201040280016700075661e557

03/27/2014 15:39: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/27/2014 15:39:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:39:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/27/2014 15:39:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 359/watts Accumulated Usage: 145.90/kWh Hops left: 2
03/27/2014 15:39:00  iMeter power has changed:359W, 145.90kWh
03/27/2014 15:39:08  Running: Read iMeter
03/27/2014 15:39:09  Reading iMeter
03/27/2014 15:39:09  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/27/2014 15:39:09  [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/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
03/27/2014 15:39:09  [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/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
03/27/2014 15:39:09  [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/27/2014 15:39:09  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:39:09  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/27/2014 15:39:09  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=11111111
03/27/2014 15:39:09  [Insteon::iMeter] ACK Received for $miner_power3
03/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200025f01030280017c0007566447
03/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200025f01030280017c0007566447
03/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Saving data fragment: 02511988761486251b8200025f01030280017c0007566447
03/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Received PLM raw data: f0
03/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02511988761486251b8200025f01030280017c0007566447
03/27/2014 15:39:09  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200025f01030280017c0007566447f0
03/27/2014 15:39:09  [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: 8200025f01030280017c0007566447f0
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 025f01030280017c0007566447f0

03/27/2014 15:39:09  [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/27/2014 15:39:09  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/27/2014 15:39:09  [Insteon::BaseInterface] Processing message for $miner_power3
03/27/2014 15:39:09  [Insteon::iMeter] received status for $miner_power3. Current Usage: 380/watts Accumulated Usage: 145.90/kWh Hops left: 2
03/27/2014 15:39:09  iMeter power has changed:380W, 145.90kWh

There is one apparent artifact remaining at 15:37:51, but it appears to be benign.

@peloy
Copy link
Collaborator

peloy commented Mar 27, 2014

Hi Kevin,

On 03/27/2014 02:34 PM, Kevin Robert Keegan wrote:

[...]

Currently, I am thinking that the best solution is to no longer skip
duplicate messages. They rarely happen, and when they do they are most
likely intentional.

Is this related to duplicated messages received from a device reporting
status? For example, a motion sensor reporting motion and the PLM
receiving the same message within a short amount of time? Hopefully it's
not related but if it is then this would break something. For example, I
use a button in a KeypadLinc to open my garage door. Before you came up
with a way to ignore duplicate messages one press of the KeypadLinc
button was causing the garage door to start moving in one direction
followed by movement in the other direction. This got fixed after
duplicate message detection got added by you.

I suspect you are talking about something deeper in the stack, but I
wanted to check because that duplicate message detection stuff you added
is really useful.

Cheers,

Eloy Paris.-

@krkeegan
Copy link
Collaborator Author

On Thu, Mar 27, 2014 at 3:53 PM, Eloy Paris notifications@github.comwrote:

Is this related to duplicated messages received from a device reporting
status?

Nope, unrelated. These are duplicate messages queued by MH to be sent out.

For example, a motion sensor reporting motion and the PLM
receiving the same message within a short amount of time?

No worries, those will still be ignored.

@krkeegan
Copy link
Collaborator Author

03/27/2014 15:37:51 [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place. Moving on...

That is somewhat benign, but I think it means that I am failing to clear a message somewhere. Let me see if I can find the bug.

@krkeegan
Copy link
Collaborator Author

Hmm, so I can't reproduce the PLM command timer expired Of course I don't have an iMeter, but injecting the same messages you received back into MH doesn't seem to produce it for me. I can't really understand why you would be seeing that message.

@rudybrian
Copy link
Contributor

I'll let it run overnight and see if it appears again.

@peloy
Copy link
Collaborator

peloy commented Mar 28, 2014

On 03/27/2014 07:03 PM, Kevin Robert Keegan wrote:

On Thu, Mar 27, 2014 at 3:53 PM, Eloy Paris notifications@github.comwrote:

Is this related to duplicated messages received from a device reporting
status?

Nope, unrelated. These are duplicate messages queued by MH to be sent out.

For example, a motion sensor reporting motion and the PLM
receiving the same message within a short amount of time?

No worries, those will still be ignored.

Ah okay, I thought so, but thanks for confirming.

Cheers,

Eloy Paris.-

@rudybrian
Copy link
Contributor

I looked through the logs this morning (the overnight test ran from 00:54:57-11:43:00) and found ten occurrences of this warning:

03/28/2014 00:55:01  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/28/2014 00:55:03  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/28/2014 01:21:01  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/28/2014 03:21:01  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/28/2014 03:55:01  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/28/2014 04:24:01  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/28/2014 04:47:01  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/28/2014 09:23:01  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/28/2014 09:38:01  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/28/2014 10:19:03  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...

The event at 00:55:03 was induced by starting the test right before the end of the minute which caused my user code to fire before MH was done initializing all the Insteon devices as was seen before.

Here is an excerpt of the log around the event at 01:21:01:

03/28/2014 01:19:00  Reading iMeter (scheduled)
03/28/2014 01:19:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/28/2014 01:19: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/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
03/28/2014 01:19: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/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
03/28/2014 01:19: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/28/2014 01:19:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/28/2014 01:19:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/28/2014 01:19:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1112111121
03/28/2014 01:19:00  [Insteon::iMeter] ACK Received for $miner_power3
03/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b820003750104
03/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b820003750104
03/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Saving data fragment: 02511988761486251b820003750104
03/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0280020f0007863f3108
03/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02511988761486251b820003750104
03/28/2014 01:19:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200037501040280020f0007863f3108
03/28/2014 01:19: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: 8200037501040280020f0007863f3108
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 037501040280020f0007863f3108

03/28/2014 01:19: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/28/2014 01:19:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/28/2014 01:19:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/28/2014 01:19:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 527/watts Accumulated Usage: 149.61/kWh Hops left: 2
03/28/2014 01:19:00  iMeter power has changed:527W, 149.61kWh
03/28/2014 01:20:00  Reading iMeter (scheduled)
03/28/2014 01:20:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/28/2014 01:20:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/28/2014 01:20: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/28/2014 01:20:00  Livingroom temperature: 90.10 F
03/28/2014 01:20:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006025019887614862521820002511988761486251b820003970104029002110007865a1d04
03/28/2014 01:20:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006025019887614862521820002511988761486251b820003970104029002110007865a1d04
03/28/2014 01:20: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/28/2014 01:20:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/28/2014 01:20:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 025019887614862521820002511988761486251b820003970104029002110007865a1d04
03/28/2014 01:20: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/28/2014 01:20:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/28/2014 01:20:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/28/2014 01:20:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1111211112
03/28/2014 01:20:00  [Insteon::iMeter] ACK Received for $miner_power3
03/28/2014 01:20:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b820003970104029002110007865a1d04
03/28/2014 01:20: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: 820003970104029002110007865a1d04
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 03970104029002110007865a1d04

03/28/2014 01:20: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/28/2014 01:20:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/28/2014 01:20:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/28/2014 01:20:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 529/watts Accumulated Usage: 149.62/kWh Hops left: 2
03/28/2014 01:20:00  iMeter power has changed:529W, 149.62kWh
03/28/2014 01:21:00  Reading iMeter (scheduled)
03/28/2014 01:21:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/28/2014 01:21: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/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
03/28/2014 01:21: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/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
03/28/2014 01:21: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/28/2014 01:21:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/28/2014 01:21:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/28/2014 01:21:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1111121111
03/28/2014 01:21:00  [Insteon::iMeter] ACK Received for $miner_power3
03/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200
03/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200
03/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Saving data fragment: 02511988761486251b8200
03/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 037101040290020c00078675dbb5
03/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Prepending prior data fragment: 02511988761486251b8200
03/28/2014 01:21:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200037101040290020c00078675dbb5
03/28/2014 01:21: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: 8200037101040290020c00078675dbb5
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 037101040290020c00078675dbb5

03/28/2014 01:21: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/28/2014 01:21:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/28/2014 01:21:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/28/2014 01:21:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 524/watts Accumulated Usage: 149.63/kWh Hops left: 2
03/28/2014 01:21:00  iMeter power has changed:524W, 149.63kWh
03/28/2014 01:21:01  [Insteon_PLM] DEBUG2: PLM command timer expired but no transmission in place.  Moving on...
03/28/2014 01:22:00  Reading iMeter (scheduled)
03/28/2014 01:22:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
03/28/2014 01:22:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
03/28/2014 01:22: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/28/2014 01:22:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
03/28/2014 01:22:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
03/28/2014 01:22: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/28/2014 01:22:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
03/28/2014 01:22:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
03/28/2014 01:22:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
03/28/2014 01:22: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/28/2014 01:22:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
03/28/2014 01:22:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
03/28/2014 01:22:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1111112111
03/28/2014 01:22:00  [Insteon::iMeter] ACK Received for $miner_power3
03/28/2014 01:22:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b820003740104029002110007868f8fcb
03/28/2014 01:22:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b820003740104029002110007868f8fcb
03/28/2014 01:22: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: 820003740104029002110007868f8fcb
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 03740104029002110007868f8fcb

03/28/2014 01:22: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/28/2014 01:22:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
03/28/2014 01:22:00  [Insteon::BaseInterface] Processing message for $miner_power3
03/28/2014 01:22:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 529/watts Accumulated Usage: 149.64/kWh Hops left: 2
03/28/2014 01:22:00  iMeter power has changed:529W, 149.64kWh

BIIIIIG Bug this was causing the PLM device id to be identified wrong, leading to bad links and yadda yadda.
@krkeegan
Copy link
Collaborator Author

I just patched a large bug in the parser, please update if you are using this branch. Otherwise any links you create will be wrong.

- Add routine to request and process PLM Config Settings
- Add routine to set/unset monitor mode
- Fix Typo in Command Length
- Fix message parsing of broadcast messages.  The message is not that long.  Not sure what is_master is supposed to be, seems like it can only be cmd1, dev_attributes makes sense.
@rudybrian
Copy link
Contributor

After running the new code for a few days I had the iMeter go deaf on me after the read at 11:04:

04/02/2014 11:04:00  Reading iMeter (scheduled)
04/02/2014 11:04:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
04/02/2014 11:04:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
04/02/2014 11:04: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

04/02/2014 11:04:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 026219887605820006
04/02/2014 11:04:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 026219887605820006
04/02/2014 11:04: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

04/02/2014 11:04:00  [Insteon_PLM] DEBUG3: Received PLM acknowledge: obj=$miner_power3; command=imeter_query; extra=00
04/02/2014 11:04:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 0250198876148625218200
04/02/2014 11:04:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 0250198876148625218200
04/02/2014 11:04: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

04/02/2014 11:04:00  [Insteon::BaseInterface] DEBUG3: PLM command:insteon_received; Device command:imeter_query; type:direct; group:
04/02/2014 11:04:00  [Insteon::BaseObject] DEBUG3: Adding hop count of 1 to hop_array of $miner_power3
04/02/2014 11:04:00  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=1111111111
04/02/2014 11:04:00  [Insteon::iMeter] ACK Received for $miner_power3
04/02/2014 11:04:00  [Insteon_PLM] DEBUG3: Received PLM raw data: 02511988761486251b8200037e010202900212000a6bbdcdd0
04/02/2014 11:04:00  [Insteon_PLM] DEBUG3: Processing PLM raw data: 02511988761486251b8200037e010202900212000a6bbdcdd0
04/02/2014 11:04: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: 8200037e010202900212000a6bbdcdd0
                       Cmd 1: 82 Insteon command not decoded
                       Cmd 2: 00
                      D1-D14: 037e010202900212000a6bbdcdd0

04/02/2014 11:04: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.
04/02/2014 11:04:00  [Insteon::BaseInterface] DEBUG: PLM command:insteon_ext_received; Device command:imeter_query; type:direct; group:
04/02/2014 11:04:00  [Insteon::BaseInterface] Processing message for $miner_power3
04/02/2014 11:04:00  [Insteon::iMeter] received status for $miner_power3. Current Usage: 530/watts Accumulated Usage: 207.21/kWh Hops left: 2
04/02/2014 11:04:00  iMeter power has changed:530W, 207.21kWh
04/02/2014 11:05:00  Reading iMeter (scheduled)
04/02/2014 11:05:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
04/02/2014 11:05:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
04/02/2014 11:05: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

04/02/2014 11:05:00  Livingroom temperature: 85.20 F
04/02/2014 11:05:00  Running: Weatherbug LiveWeather
04/02/2014 11:05:00  Weatherbug location liveweather.
04/02/2014 11:05:01  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 1 attempts.
04/02/2014 11:05:01  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
04/02/2014 11:05:01  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=2111111111
04/02/2014 11:05:01  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 1.73 seconds; starting hop-count: 1
04/02/2014 11:05:01  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
04/02/2014 11:05: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

04/02/2014 11:05:03  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 2 attempts.
04/02/2014 11:05:03  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
04/02/2014 11:05:03  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=2211111111
04/02/2014 11:05:03  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 3.43 seconds; starting hop-count: 1
04/02/2014 11:05:03  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
04/02/2014 11:05: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

04/02/2014 11:05:05  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 3 attempts.
04/02/2014 11:05:05  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
04/02/2014 11:05:05  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=2221111111
04/02/2014 11:05:05  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 5.14 seconds; starting hop-count: 1
04/02/2014 11:05:05  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
04/02/2014 11:05: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

04/02/2014 11:05:06  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 4 attempts.
04/02/2014 11:05:06  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
04/02/2014 11:05:06  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=1 :: hop_array[]=2222111111
04/02/2014 11:05:06  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 6.88 seconds; starting hop-count: 1
04/02/2014 11:05:06  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
04/02/2014 11:05: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

04/02/2014 11:05:08  [Insteon::BaseInterface] WARN: number of retries (5) for obj=$miner_power3; command=imeter_query; extra=00 exceeds limit.  Now moving on...
04/02/2014 11:06:00  Reading iMeter (scheduled)
04/02/2014 11:06:00  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 0.00 seconds; starting hop-count: 1
04/02/2014 11:06:00  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0262198876058200
04/02/2014 11:06: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

04/02/2014 11:06:01  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 1 attempts.
04/02/2014 11:06:01  [Insteon::BaseObject] DEBUG3: Adding hop count of 2 to hop_array of $miner_power3
04/02/2014 11:06:01  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=2 :: hop_array[]=2222211111
04/02/2014 11:06:01  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 1.71 seconds; starting hop-count: 2
04/02/2014 11:06:01  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 02621988760a8200
04/02/2014 11:06: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

04/02/2014 11:06:03  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 2 attempts.
04/02/2014 11:06:03  [Insteon::BaseObject] DEBUG3: Adding hop count of 3 to hop_array of $miner_power3
04/02/2014 11:06:03  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=2 :: hop_array[]=3222221111
04/02/2014 11:06:03  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 3.62 seconds; starting hop-count: 2
04/02/2014 11:06:03  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 02621988760a8200
04/02/2014 11:06: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

04/02/2014 11:06:05  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 3 attempts.
04/02/2014 11:06:05  [Insteon::BaseObject] DEBUG3: Adding hop count of 3 to hop_array of $miner_power3
04/02/2014 11:06:05  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=2 :: hop_array[]=3322222111
04/02/2014 11:06:05  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 5.53 seconds; starting hop-count: 2
04/02/2014 11:06:05  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 02621988760a8200
04/02/2014 11:06: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

04/02/2014 11:06:07  [Insteon::BaseMessage] WARN: now resending obj=$miner_power3; command=imeter_query; extra=00 after 4 attempts.
04/02/2014 11:06:07  [Insteon::BaseObject] DEBUG3: Adding hop count of 3 to hop_array of $miner_power3
04/02/2014 11:06:07  [Insteon::BaseObject] DEBUG4: $miner_power3->default_hop_count()=2 :: hop_array[]=3332222211
04/02/2014 11:06:07  [Insteon_PLM] DEBUG2: Sending obj=$miner_power3; command=imeter_query; extra=00 incurred delay of 7.44 seconds; starting hop-count: 2
04/02/2014 11:06:07  [Insteon_PLM] DEBUG3: Sending  PLM raw data: 02621988760a8200
04/02/2014 11:06: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

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

Restarting MH seems to clear it up and the iMeter starts responding again.

@krkeegan
Copy link
Collaborator Author

krkeegan commented Apr 3, 2014

In that particular instance, your PLM simply stopped responding. Based on the logs, I really can't say why, nor do I know why a restart would fix it.

@rudybrian
Copy link
Contributor

Thanks @krkeegan, if it happens again I will try sending some commands to my other Insteon device before restarting to see if it behaves any differently.

@rudybrian
Copy link
Contributor

The same symptoms re-appeared earlier this morning and after noticing this time I tried sending commands to another Insteon device which behaved in the same way as the iMeter in that I see the commands being sent, but they simply time out waiting for an ack.

@krkeegan
Copy link
Collaborator Author

krkeegan commented Apr 4, 2014

Hmm, the fact that you can rectify this by restarting MH suggests that the serial connection is being broken somehow. I don't know what type of OS you are on, but are there any logs that you can review to see what might be happening?

Interestingly, this is somewhat similar to an issue raised on the mailling list by Jeff Siddall with the subject "Automatically reconnect after USB Insteon PLM disconnected?"

I don't know very much about the perl interface to serial ports or how MH implements it. But your problem and Jeff's would likely be solved if we could somehow figure out a way to check the status of a serial port and if it is "down" reinitialize it.

@peloy
Copy link
Collaborator

peloy commented Apr 4, 2014

Hi guys,

A restart might fix the problem because that might cause some of the
serial control signals (DTR) to toggle, which might cause the PLM to reset.

For instance, I have an Arduino-like device that connects to my server
via USB FTDI FT232R chip. I've noticed that the device resets every time
I open the serial port.

Cheers,

Eloy Paris.-

On 04/04/2014 02:50 PM, Kevin Robert Keegan wrote:

Hmm, the fact that you can rectify this by restarting MH suggests that
the serial connection is being broken somehow. I don't know what type of
OS you are on, but are there any logs that you can review to see what
might be happening?

Interestingly, this is somewhat similar to an issue raised on the
mailling list by Jeff Siddall with the subject "Automatically reconnect
after USB Insteon PLM disconnected?"

I don't know very much about the perl interface to serial ports or how
MH implements it. But your problem and Jeff's would likely be solved if
we could somehow figure out a way to check the status of a serial port
and if it is "down" reinitialize it.


Reply to this email directly or view it on GitHub
#388 (comment).

@rudybrian
Copy link
Contributor

My MH test box is running CentOS 6.3 (kernel 2.6.32-279.19.1.el6.x86_64) at the moment.

After digging through the logs, I do indeed see the USB PLM disconnecting and reconnecting.The dates seem to match, but the time of the disconnect/reconnect seems to be a few hours later than when MH stops getting acks from the Insteon devices.

@rudybrian
Copy link
Contributor

I looked a bit more into the time discrepancy between events, and it would appear to be related to my server's log time and system time being offset by a few hours. Removing the time offset seems to to correlate with the disconnect/reconnect events and MH loosing connectivity.

@krkeegan
Copy link
Collaborator Author

This appears to be good, with the exception of the power cycling problems, which are not really an issue with this commit. I have created #397 for discussion of that particular issue.

krkeegan added a commit that referenced this pull request Apr 15, 2014
Completely Rewritten Insteon Message Parser
@krkeegan krkeegan merged commit 0731cbf into hollie:master Apr 15, 2014
@krkeegan krkeegan deleted the plm_parser branch June 13, 2014 23:56
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants