[mh] Misterhouse time issue

Dean Junk <[email protected]> Fri, 27 Dec 2019 22:09:44 +0000

Newsgroups	gmane.comp.misc.misterhouse.user
Message-ID	<DM6PR15MB34179B5CAF018214A7088B3BD12A0@DM6PR15MB3417.namprd15.prod.outlook.com>

On all newer versions of Linux, I have hit an issue I can't figure out how to fix. I've been using misterhouse for about the last 10 years, so this is a bit of a mystery. When misterhouse starts up, everything looks good (no errors and code compiles). However, the time never changes. Below is a sample from my console (the highlighted is from my logging using localtime):

27/12/2019 03:48:44 PM [Insteon::BaseObject] Ignoring unsupported command from $thermostat
27/12/2019 03:48:44 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/familyRoom/familyRoomMotion , M: off
27/12/2019 03:48:44 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once home/familyRoom/familyRoomMotion
  6f 66 66                                         off,
27/12/2019 03:48:44 PM *** mqtt mqtt_Item nom to MQTT to MH $Z_FamilyRoom_Motion::set(off, mqtt=HASH(0x556b5f4c8300))
27/12/2019 03:48:44 PM *** mqtt zwave_controller read_mqtt_msg Ping Request
27/12/2019 03:48:44 PM *** mqtt zwave_controller check_for_data Ping rcvd: PingResp/at-most-once
27/12/2019 03:48:44 PM 2019-12-27 15:50:46 - Garage timer expired!

I have attached more logging in a file to keep the email brief. The other issue is that since the time doesn't change, none of my cron time entries fire. Any help would be greatly appreciated!!

I have tried fresh install on the latest version of ubuntu, fedora, and manjaro (all the same results).

________________________________________________________
To unsubscribe from this list, go to: https://lists.sourceforge.net/lists/listinfo/misterhouse-users

mh.log (text/x-log, 37.8 KB)

ommand: mh 
Pgm  path   : /home/mhuser/misterhouse/bin
Pgm  version: 5.0  
Last updated: Fri Dec 27 14:26:32 2019
Perl version: 5.030000
OS   version: linux linux  
Other       : user=mhuser pid=2990 box=dell-lat3340-enabledsoftware-net cpu=-

This program is free software; you can redistribute it and/or
modify it under the terms of the GNU General Public License
as published by the Free Software Foundation; either version 2
of the License, or (at your option) any later version.

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

You should have received a copy of the GNU General Public License
along with this program; if not, write to the Free Software
Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.

Read parameter files: ./mh.ini ./mh.private.ini /home/mhuser/code/mh.private.ini
Debugging for insteon turned on
Debugging for x10 turned on
Debugging for w800 turned on
Code Directories:
 - /home/mhuser/code/
 - ./../code/common
Loading other modules
Starting setup
 - using simple Text distance function
 - read 2 trigger entries
 - reading previous log files
 - archiving previous /home/mhuser/data//logs/*.log files ....
 - creating http            on tcp   8080 raw
 - creating server mhsend   on tcp   8084 buffered
 - creating server telnet   on tcp   1234 raw
 - creating xap_send        on udp  3639 send
 - creating xap_listen_core on udp 49152 listen
 - creating xpl_send        on udp  3865 send
 - creating xpl_listen      on udp 49352 listen
 - initializing state tracker ...
 - creating W800 port on /dev/serial/by-id/usb-Prolific_Technology_Inc._USB-Serial_Controller-if00-port0
can't open device: /dev/serial/by-id/usb-Prolific_Technology_Inc._USB-Serial_Controller-if00-port0
 at /home/mhuser/misterhouse/bin/mh line 6538.


Can't open serial port /dev/serial/by-id/usb-Prolific_Technology_Inc._USB-Serial_Controller-if00-port0: No such file or directory

27/12/2019 03:57:42 PM [Insteon_PLM] serial:/dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A600B3FN-if00-port0:19200
 - creating Insteon PLM port on /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A600B3FN-if00-port0
 - object logging disabled
 - process id 2990 written to /home/mhuser/data//mh.pid
 - external command file (xcmd_file): ./../house_cmd.txt
 - HTML file     : ./../web/ia5/index.shtml

Warning:  password_file /home/mhuser/data//.password not found.  Run mh/bin/set_password

Done with setup

27/12/2019 03:57:42 PM [IA7_Collection_Updater] : Starting
27/12/2019 03:57:42 PM [IA7_Collection_Updater] : Reviewing ./../data/web/collections.json to current version 1.4
27/12/2019 03:57:42 PM [IA7_Collection_Updater] : Finished
27/12/2019 03:57:42 PM Perl @INC contains: /home/mhuser/code/, ./../code/common, /home/mhuser/misterhouse/bin/../lib, /home/mhuser/misterhouse/bin/../lib/site, ., /usr/local/lib64/perl5/5.30, /usr/local/share/perl5/5.30, /usr/lib64/perl5/vendor_perl, /usr/share/perl5/vendor_perl, /usr/lib64/perl5, /usr/share/perl5
27/12/2019 03:57:42 PM Reading /home/mhuser/code/mh.private.ini and mh.ini
   html_alias alias /photos_big dir does not exist, dir=/home/mhuser/data//photos
   html_alias alias /rrd dir does not exist, dir=/home/mhuser/data//rrd
   html_alias alias /photos dir does not exist, dir=/home/mhuser/data//photos
   html_alias alias /email dir does not exist, dir=/home/mhuser/data//email
   html_alias alias /tv dir does not exist, dir=/home/mhuser/data//tv
Voice names: Microsoft Mary, Microsoft Mike, Microsoft Sam
Read 4 entries from ./../data/pronouncable_words.list

Error, could not find the caller id file /home/mhuser/data//phone/phone.caller_id.list: No such file or directory
27/12/2019 03:57:42 PM Reading 1 .mht table files: insteon.mht
27/12/2019 03:57:42 PM Translating insteon.mht -> /home/mhuser/code//insteon.mhp
27/12/2019 03:57:42 PM Initialized read_table_A.pl
Reading code_dirs: /home/mhuser/code/ ./../code/common
27/12/2019 03:57:42 PM Reading 17 code files
27/12/2019 03:57:42 PM Evaluating user code
27/12/2019 03:57:42 PM [Insteon_PLM] 2412[US] using serial,  serial_port=/dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A600B3FN-if00-port0
27/12/2019 03:57:42 PM [Insteon] Setting up initialization hooks
27/12/2019 03:57:42 PM [Insteon_PLM] setting default xmit delay to: .25
27/12/2019 03:57:42 PM [Insteon_PLM] setting x10 xmit delay to: 0.5
[X10_Sensor] class=X10_Sensor, id=C2, name=X10_Office_Motion, interface=
Warning: Dummy_Interface #0: Creating dummy interface for id=C2, state= and interface=.
27/12/2019 03:57:42 PM [X10_Sensor] Calling Serial_match_add_hook
[X10_Sensor] class=X10_Sensor, id=D2, name=X10_Garage_Motion, interface=
Warning: Dummy_Interface #1: Creating dummy interface for id=D2, state= and interface=.
[X10_Sensor] class=X10_Sensor, id=E2, name=X10_Mini_Motion, interface=
Warning: Dummy_Interface #2: Creating dummy interface for id=E2, state= and interface=.
[X10_Sensor] class=X10_Sensor, id=K2, name=X10_BackDoor_Motion, interface=
Warning: Dummy_Interface #3: Creating dummy interface for id=K2, state= and interface=.
27/12/2019 03:57:42 PM *** Creating zwave_controller on 0.0.0.0:0 home/#
27/12/2019 03:57:42 PM *** Opening MQTT (zwave_controller) connection to 0.0.0.0/0/home/#
27/12/2019 03:57:42 PM *** Host       = 0.0.0.0
27/12/2019 03:57:42 PM *** Port       = 0
27/12/2019 03:57:42 PM *** Topic      = home/#
27/12/2019 03:57:42 PM *** User       = 
27/12/2019 03:57:42 PM *** Password   = 
27/12/2019 03:57:42 PM *** Keep Alive = 121
27/12/2019 03:57:42 PM *** mqtt mqtt_connect Socket (0.0.0.0:0,0) 
27/12/2019 03:57:42 PM *** mqtt Socket check (121) [  ]: Connected
27/12/2019 03:57:42 PM *** mqtt zwave_controller Received: ConnAck/at-most-once Connection Accepted 
27/12/2019 03:57:42 PM *** mqtt zwave_controller Sub 1 Received: (--No $$msg{string}--)
27/12/2019 03:57:42 PM *** mqtt zwave_controller Initializing MQTT connection ...
27/12/2019 03:57:42 PM *** mqtt added MQTT check_for_data ...

27/12/2019 03:57:42 PM Oops1: Use of uninitialized value in concatenation (.) or string at /home/mhuser/misterhouse/bin/../lib/mqtt.pm line 778.

27/12/2019 03:57:42 PM *** mqtt mqtt set zwave_controller: [(on), (mqtt=HASH(0x55ebdf808430)), ]
27/12/2019 03:57:42 PM *** mqtt mqtt set zwave_controller: isa mqtt

Good code saved
27/12/2019 03:57:42 PM FUNCTION: set_volume_pre_hook
27/12/2019 03:57:42 PM running: play ./../sounds/sound_click1.wav

Restoring object states
ALSA lib pulse.c:242:(pulse_connect) PulseAudio: Unable to connect: Connection refused

play FAIL ao: startwrite [ao driver]: Corrupted encoding data (bits per sample should not be zero)
play FAIL sox: Sorry, there is no default audio device configured
Object states restored
27/12/2019 03:57:42 PM IA7 Speech Notifications enabled
27/12/2019 03:57:42 PM Generating Voice commands for all Insteon objects
Activating voice commands
Starting monitor commands loop

27/12/2019 03:57:42 PM [Insteon_PLM] WARN: encountered garbled PLM data '026239a11400200606' but expected '026239a11405200606'. Attempting to find next valid message.
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/officePlug , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/officePlug 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM Rereading .menu code files.
27/12/2019 03:57:42 PM Organizer: Calendar matches target schema and does not require upgrading
27/12/2019 03:57:42 PM Organizer: Todo matches target schema and does not require upgrading
27/12/2019 03:57:42 PM Organizer: Reading updated organizer calendar file now
27/12/2019 03:57:42 PM Evaluating code organizer_events
27/12/2019 03:57:42 PM Organizer: Reading updated organizer todo file
Bad time format:  12:00 am + 23:59   caller=main /home/mhuser/misterhouse/bin/mh 7411
db mday=27 mdayf=4 min=57 minf=00 secf=0 hour=15 hourf=12 ap=AM m=12 mf=14 y=119 yf=137
27/12/2019 03:57:42 PM Evaluating code organizer_tasks
Opened database successfully
27/12/2019 03:57:42 PM [Insteon::IOLinc] Setting Momentary Time to 20 tenths of a second for $Mini_Door_IOLinc
27/12/2019 03:57:42 PM 2019-12-27 15:57:43 - Startup start.
27/12/2019 03:57:42 PM 2019-12-27 15:57:43 - Startup end.
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/officePlugLeft , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/officePlugLeft 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/officePlugRight , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/officePlugRight 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/office/officePlug , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/office/officePlug 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/office/officePlugLeft , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/office/officePlugLeft 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/office/officePlugRight , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/office/officePlugRight 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/office/officeMotion , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/office/officeMotion 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Z_Office_Motion::set(off, mqtt=HASH(0x55ebdf808430))
27/12/2019 03:57:42 PM [Insteon::IOLinc] Acknowledged flag set for $Garage_Door_IOLinc
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/office/officeHumidity , M: 38.25
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/office/officeHumidity 
  33 38 2e 32 35                                   38.25,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Office_Humidity::set(38.25, mqtt=HASH(0x55ebdf808430))
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/office/officeLight , M: 1.5599999
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/office/officeLight 
  31 2e 35 35 39 39 39 39 39                       1.5599999,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Office_Light::set(1.5599999, mqtt=HASH(0x55ebdf808430))
2019-12-27 15:57:43 - *** Dean *** Z-Wave office_humidity = Generic_Item=HASH(0x55ebdf4b49e8)!
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/office/officeTemp , M: 21.4
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/office/officeTemp 
  32 31 2e 34                                      21.4,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Office_Temp::set(21.4, mqtt=HASH(0x55ebdf808430))
2019-12-27 15:57:43 - *** Dean *** Z-Wave office_light = Generic_Item=HASH(0x55ebdf4b6e78)!
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/globalRoom/ankenyDaylight , M: on
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/globalRoom/ankenyDaylight 
  6f 6e                                            on,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Z_Daylight::set(on, mqtt=HASH(0x55ebdf808430))
2019-12-27 15:57:44 - *** Dean *** Z-Wave office_temp = 70.52!
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/globalRoom/ankeny , M: 41.6
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/globalRoom/ankeny 
  34 31 2e 36                                      41.6,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Z_Outdoor_Temp::set(41.6, mqtt=HASH(0x55ebdf808430))
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/furnaceRoom/batteryCharger , M: on
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/furnaceRoom/batteryCharger 
  6f 6e                                            on,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/furnaceRoom/fireAlarmSensorBurglarAlarm , M: on
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/furnaceRoom/fireAlarmSensorBurglarAlarm 
  6f 6e                                            on,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/furnaceRoom/fireAlarmSensorAccessControl , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/furnaceRoom/fireAlarmSensorAccessControl 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/furnaceRoom/fireAlarmSensor , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/furnaceRoom/fireAlarmSensor 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Z_FireAlarmSensor::set(off, mqtt=HASH(0x55ebdf808430))
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/laundry/laundryRoomLight , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/laundry/laundryRoomLight 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/deck/upperDeckLight , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/deck/upperDeckLight 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/diningRoom/diningRoomLight , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/diningRoom/diningRoomLight 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/garage/garageTiltSensorAlarm , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/garage/garageTiltSensorAlarm 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/garage/garageTiltSensor , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/garage/garageTiltSensor 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Z_GarageTiltSensor::set(off, mqtt=HASH(0x55ebdf808430))
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/garage/garageTiltSensorBattery , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/garage/garageTiltSensorBattery 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Z_GarageTiltSensorBattery::set(off, mqtt=HASH(0x55ebdf808430))
27/12/2019 03:57:42 PM 2019-12-27 15:57:45 - Garage Door Closed
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/garage/backDoor , M: close
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/garage/backDoor 
  63 6c 6f 73 65                                   close,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/frontEntry/frontDoor , M: close
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/frontEntry/frontDoor 
  63 6c 6f 73 65                                   close,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/basementFamilyRoom/basementFamilyRoomPlugRight , M: on
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/basementFamilyRoom/basementFamilyRoomPlugRight 
  6f 6e                                            on,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/basementFamilyRoom/basementFamilyRoomPlugLeft , M: on
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/basementFamilyRoom/basementFamilyRoomPlugLeft 
  6f 6e                                            on,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/basementFamilyRoom/basementFamilyRoomPlug , M: on
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/basementFamilyRoom/basementFamilyRoomPlug 
  6f 6e                                            on,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/familyRoom/familyRoomPlug , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/familyRoom/familyRoomPlug 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/familyRoom/familyRoomPlugLeft , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/familyRoom/familyRoomPlugLeft 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/familyRoom/familyRoomPlugRight , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/familyRoom/familyRoomPlugRight 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/familyRoom/familyRoomMotion , M: off
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/familyRoom/familyRoomMotion 
  6f 66 66                                         off,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Z_FamilyRoom_Motion::set(off, mqtt=HASH(0x55ebdf808430))
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$Mini_Door_IOLinc; command=set_operating_flags; extra=06 after 1 attempts.
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/familyRoom/familyRoomHumidity , M: 37.69
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/familyRoom/familyRoomHumidity 
  33 37 2e 36 39                                   37.69,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $FamilyRoom_Humidity::set(37.69, mqtt=HASH(0x55ebdf808430))
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/familyRoom/familyRoomTemp , M: 23.2
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/familyRoom/familyRoomTemp 
  32 33 2e 32                                      23.2,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $FamilyRoom_Temp::set(23.2, mqtt=HASH(0x55ebdf808430))
2019-12-27 15:57:45 - *** Dean *** Z-Wave familyroom_humidity = Generic_Item=HASH(0x55ebdf4bdc58)!
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/familyRoom/familyRoomLightLevel , M: 10.97
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once,retain home/familyRoom/familyRoomLightLevel 
  31 30 2e 39 37                                   10.97,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $FamilyRoom_LightLevel::set(10.97, mqtt=HASH(0x55ebdf808430))
2019-12-27 15:57:45 - *** Dean *** Z-Wave familyroom_temp = 73.76!
2019-12-27 15:57:46 - *** Dean *** Z-Wave familyroom_light = Generic_Item=HASH(0x55ebdf4be8a0)!
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$Mini_Door_IOLinc; command=set_operating_flags; extra=06 after 2 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$Mini_Door_IOLinc; command=set_operating_flags; extra=06 after 3 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$Mini_Door_IOLinc; command=set_operating_flags; extra=06 after 4 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseInterface] WARN: number of retries (5) for obj=$Mini_Door_IOLinc; command=set_operating_flags; extra=06 exceeds limit.  Now moving on...
27/12/2019 03:57:42 PM [Insteon_PLM] PLM id: 41ef65 firmware: 9e
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$OBI_Plug; command=get_engine_version after 1 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $OBI_Plug of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $XMAS_Tree3 of I2. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $XMAS_Tree2 of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $XMAS_Tree of I2CS. hops left: 3
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Garage_XMAS_Lights of I2. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$House_XMAS_Lights; command=get_engine_version after 1 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$House_XMAS_Lights; command=get_engine_version after 2 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$House_XMAS_Lights; command=get_engine_version after 3 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$House_XMAS_Lights; command=get_engine_version after 4 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseInterface] WARN: number of retries (5) for obj=$House_XMAS_Lights; command=get_engine_version exceeds limit.  Now moving on...
27/12/2019 03:57:42 PM [Insteon::BaseInterface] WARN: Message Timeout:  Now calling callback: $House_XMAS_Lights->_get_engine_version_failure();
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$China_Hutch; command=get_engine_version after 1 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $China_Hutch of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $MB_Accent of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Floor_Lamp of I2CS. hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseInterface] WARN! Dropped duplicate incoming message 273ac141ef65220d02, from $Floor_Lamp
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Family_Room_Lamp of I2CS. hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Kitchen_Sink_Recessed of I2CS. hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Kitchen_Desk_Accent of I2CS. hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Garage_Light of I2CS. hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Kitchen_Sink_Accent of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Front_House_UpLights of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Firepit_Lights of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Gazebo_Lights of I2CS. hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseInterface] WARN! Dropped duplicate incoming message 2147af41ef65220d02, from $Gazebo_Lights
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $ECenter_Top of I2. hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Garage_Path of I2. hops left: 2
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Mini_Garage_Light of I2. hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $BasementStairsTop of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $BasementSconceStairs of I1. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $BasementSconceFP of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $ECenter_Sides of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Office_Sconce of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Office_Main of I2. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Kitchen_Table of I2CS. hops left: 2
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$Inside_Entry; command=get_engine_version after 1 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$Inside_Entry; command=get_engine_version after 2 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Inside_Entry of I1. hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseInterface] WARN! Dropped duplicate incoming message 03669141ef65220d00, from $Inside_Entry
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$Outside_Entry; command=get_engine_version after 1 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Outside_Entry of I2. hops left: 2
27/12/2019 03:57:42 PM [Insteon::BaseInterface] WARN! Dropped duplicate incoming message 150de041ef65230d01, from $Outside_Entry
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$ezrain; command=get_engine_version after 1 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $ezrain of I2. hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Office_Accent of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Hot_Water_Pump of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Bedroom_Hallway of I2. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseInterface] WARN! Dropped duplicate incoming message 15b2a741ef65210d01, from $Bedroom_Hallway
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $MB_Cans of I2. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $MB_Ceiling_Fan of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $thermostat of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Garage_Door_IOLinc with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Garage_Door_IOLinc::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $OBI_Plug with on-level: 100%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $OBI_Plug::set_receive(on, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $XMAS_Tree3 with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $XMAS_Tree3::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $XMAS_Tree2 with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $XMAS_Tree2::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $XMAS_Tree with on-level: 0%, hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] $XMAS_Tree::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Garage_XMAS_Lights with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Garage_XMAS_Lights::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $China_Hutch with on-level: 0%, hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] $China_Hutch::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $MB_Accent with on-level: 0%, hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] $MB_Accent::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Floor_Lamp with on-level: 0%, hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Floor_Lamp::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Family_Room_Lamp with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Family_Room_Lamp::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Kitchen_Sink_Recessed with on-level: 0%, hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Kitchen_Sink_Recessed::set_receive(off, $PLM)
27/12/2019 03:57:42 PM 2019-12-27 15:58:48 - Kitchen Sink Recessed OFF
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Kitchen_Desk_Accent with on-level: 0%, hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Kitchen_Desk_Accent::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Garage_Light with on-level: 0%, hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Garage_Light::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Kitchen_Sink_Accent with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Kitchen_Sink_Accent::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Front_House_UpLights with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Front_House_UpLights::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Firepit_Lights with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Firepit_Lights::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Gazebo_Lights with on-level: 0%, hops left: 2
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Gazebo_Lights::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $ECenter_Top with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $ECenter_Top::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Garage_Path with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Garage_Path::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Mini_Garage_Light with on-level: 0%, hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Mini_Garage_Light::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $BasementStairsTop with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $BasementStairsTop::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $BasementSconceStairs with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $BasementSconceStairs::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] $BasementSconceFP::set(off, $BasementSconceStairs)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $BasementSconceFP with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $BasementSconceFP::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] Ignoring duplicate set off state command for $BasementSconceFP received in less than 1000 milliseconds
27/12/2019 03:57:42 PM [Insteon::BaseObject] received command/state acknowledge from $BasementSconceFP: (unknown) and data: 00
27/12/2019 03:57:42 PM [Insteon::BaseObject] $BasementSconceStairs::set(off, $BasementSconceFP)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $ECenter_Sides with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $ECenter_Sides::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Office_Sconce with on-level: 100%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Office_Sconce::set_receive(100%, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Office_Main with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Office_Main::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Kitchen_Table with on-level: 0%, hops left: 1
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Kitchen_Table::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Inside_Entry with on-level: 0%, hops left: 2
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Inside_Entry::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$Outside_Entry; command=status_request after 1 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseMessage] WARN: now resending obj=$Outside_Entry; command=status_request after 2 attempts.
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Outside_Entry with on-level: 0%, hops left: 2
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Outside_Entry::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseInterface] WARN! Dropped duplicate incoming message 150de041ef65260000, from $Outside_Entry
27/12/2019 03:57:42 PM [Insteon::Irrigation] active_valve_id: 1, valve_is_running: 0, active_program: 1, program_is_running: 0, pump_enabled: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Office_Accent with on-level: 100%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Office_Accent::set_receive(on, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Hot_Water_Pump with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Hot_Water_Pump::set_receive(off, $PLM)
27/12/2019 03:57:42 PM 2019-12-27 15:59:07 - Hot water pump OFF
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $Bedroom_Hallway with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $Bedroom_Hallway::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $MB_Cans with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $MB_Cans::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::BaseObject] received status for $MB_Ceiling_Fan with on-level: 0%, hops left: 0
27/12/2019 03:57:42 PM [Insteon::BaseObject] $MB_Ceiling_Fan::set_receive(off, $PLM)
27/12/2019 03:57:42 PM [Insteon::Thermostat] Processing is_info_request for thermostat_get_zone_info with value: 8e
27/12/2019 03:57:42 PM [Insteon::IOLinc] Acknowledged flag set for $Garage_Door_IOLinc
27/12/2019 03:57:42 PM [Insteon::BaseObject] received command/state acknowledge from $BasementSconceFP: off and data: 00
27/12/2019 03:57:42 PM [Insteon::BaseObject] received command/state acknowledge from $BasementSconceStairs: off and data: 00
27/12/2019 03:57:42 PM [Insteon::Thermo_i2CS] Processing is_info_request for thermostat_control with value: 03
27/12/2019 03:57:42 PM [Insteon::BaseInterface] WARN queuing a duplicate command already in queue.
27/12/2019 03:57:42 PM [Insteon::IOLinc] Acknowledged flag set for $Garage_Door_IOLinc
27/12/2019 03:57:42 PM [Insteon::Thermostat] Processing data for thermostat_control with value: 03
27/12/2019 03:57:42 PM [Insteon::BaseObject] received engine version for $Garage_Door_IOLinc of I2CS. hops left: 0
27/12/2019 03:57:42 PM [Insteon::Thermostat] Processing is_info_request for thermostat_get_zone_info with value: 8e
27/12/2019 03:57:42 PM [Insteon::BaseInterface] Received message from: $thermostat; command: thermostat_get_zone_info; type: direct; group: 
27/12/2019 03:57:42 PM [Insteon::BaseObject] Ignoring unsupported command from $thermostat
27/12/2019 03:57:42 PM *** mqtt zwave_controller read_mqtt_msg Ping Request
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data Ping rcvd: PingResp/at-most-once
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MH to MQTT ($Z_FrontDoorLock) no p_setby ::set($msg, $p_setby)
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MH to MQTT ($Z_BackDoorLock) no p_setby ::set($msg, $p_setby)
27/12/2019 03:57:42 PM 2019-12-27 15:59:45 - Garage timer expired!
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/frontEntry/frontDoor/set , M: close
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once home/frontEntry/frontDoor/set 
  63 6c 6f 73 65                                   close,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Z_FrontDoorLock::set(close, mqtt=HASH(0x55ebdf808430))
2019-12-27 15:59:45 - *** Dean *** Z-Wave Front Door Lock is Locked!
2019-12-27 15:59:45 - *** Dean *** Z-Wave Back Door Lock is Unlocked!
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/garage/backDoor/set , M: close
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once home/garage/backDoor/set 
  63 6c 6f 73 65                                   close,
27/12/2019 03:57:42 PM *** mqtt mqtt_Item nom to MQTT to MH $Z_BackDoorLock::set(close, mqtt=HASH(0x55ebdf808430))
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/frontEntry/frontDoor , M: close
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once home/frontEntry/frontDoor 
  63 6c 6f 73 65                                   close,
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: T:home/garage/backDoor , M: close
27/12/2019 03:57:42 PM *** mqtt zwave_controller check_for_data rcv'd: S:Publish/at-most-once home/garage/backDoor 
  63 6c 6f 73 65                                   close,