[mh] Fwd: Re: misterhouse no longer controlling the lights

Carl

    Well that was a surprise,  I don't have a current startup.log. The
one in /data/logs is from march 10 2018 ?  there are other files with
Nov 18 and 19 dates.  Looks like I better dig into why no current
startup.log..
   Well after digging I am no better off.  I thought the debug= X10 or
insteon or startup had some control over what log file was written. 
Looks like I am wrong again.

Thanks
Jim


On 11/19/21 6:17 PM, Carl McGrath wrote:
> I live in FL, where lightening and power hits are us. I have several
> dead PLMs and one or two I brought back to life with a capacitor
> replacement.
> When things seem bad in PLM space, I frst look for this segment in the
> startup log after reboot
>
>     Reading code_dirs: /home/carl/Misterhouse_5.0/cjm_local/code
>     ./../code/common
>     10/24/2021 11:52:21 AM Reading 17 code files
>     10/24/2021 11:52:21 AM Evaluating user code
>     10/24/2021 11:52:21 AM [Insteon_PLM] 2412[US] using serial,
>     serial_port=/dev/insteon_plm_cjm
>     10/24/2021 11:52:21 AM [Insteon] Setting up initialization hooks
>     10/24/2021 11:52:21 AM [Insteon_PLM] setting default xmit delay
>     to: 0.25
>     10/24/2021 11:52:21 AM [Insteon_PLM] setting x10 xmit delay to: 0.5
>
>     Good code saved
>     10/24/2021 11:52:21 AM FUNCTION: set_volume_pre_hook
>     Restoring object states
>     Object states restored
>     10/24/2021 11:52:21 AM IA7 Speech Notifications enabled
>     10/24/2021 11:52:21 AM Generating Voice commands for all Insteon
>     objects
>     Activating voice commands
>     Starting monitor commands loop
>
>     Latitude: 26.55,  Longitude: -81.99,  Time Zone: -5
>     sunrise=7:32 AM sunset=6:52 PM
>     sunrise twilight=7:09 AM sunset twilight=7:15 PM
>     The moon is Three-Quarter Waning, 86% bright, and 18 days old
>     The next full moon is on Friday, November 19th
>     10/24/2021 11:52:22 AM [Insteon_PLM] PLM id: 3c4c55 firmware: 9e
>
> If you do not see the last line, where id:3c4c55 is the Insteon
> Address 3C.4C.55 plus the PLM Firmware version, your PLM is not really
> communicating with MH
>
>
> On 11/16/21 13:11, hoodcanaljim wrote:
>> Hi
>>
>>  Last night I found that MH had stopped controlling my system. We have
>> had several power outages lately and there was one yesterday around
>> noon.  First noticed the problem when I tried to shut off the
>> $familyroom light.  In the web interface $familyroom shows as a green
>> bar (8088/ia7/) with the word "on" but when opening that link it wont
>> take a on command but with a off command it closes as expected but the
>> web interface still shows it as "on".
>>  I have a second PLM, not sure what its status is,  I am not seeing
>> anything in the status command or in the print.log that I can recognize
>> as a problem.
>>
>>  Main question: Is there a way to test the PLM thru MH that can tell me
>> if its Blown?
>>
>> Biggest problem: I haven't had to work on this system in several years
>> and I don't remember half of what I learned.  So I am turning to your
>> group for help to keep me from doing something to crash the whole
>> system.
>> Thanks
>> Jim
>>
>>
>> systemctl status mhouse -l
>> ● mhouse.service - Misterhouse Home Automation
>>    Loaded: loaded (/etc/systemd/system/mhouse.service; enabled; vendor
>> preset: disabled)
>>    Active: active (running) since Tue 2021-11-16 09:42:02 PST; 21min ago
>>  Main PID: 3542 (mh)
>>     Tasks: 1
>>    CGroup: /system.slice/mhouse.service
>>            └─3542 /usr/bin/perl /opt/mista/mh/bin/mh -tk 0
>>
>> Nov 16 09:42:03 nub mh[3542]: 11/16/21 09:42:03 AM Rereading .menu code
>> files.
>> Nov 16 09:42:03 nub mh[3542]: 11/16/21 09:42:03 AM Organizer: Calendar
>> matches target schema and does not require upgrading
>> Nov 16 09:42:03 nub mh[3542]: 11/16/21 09:42:03 AM Organizer: Todo
>> matches target schema and does not require upgrading
>> Nov 16 09:42:03 nub mh[3542]: 11/16/21 09:42:03 AM Organizer: Reading
>> updated organizer calendar file now
>> Nov 16 09:42:03 nub mh[3542]: 11/16/21 09:42:03 AM Evaluating code
>> organizer_events
>> Nov 16 09:42:03 nub mh[3542]: 11/16/21 09:42:03 AM Organizer: Reading
>> updated organizer todo file
>> Nov 16 09:42:03 nub mh[3542]: 11/16/21 09:42:03 AM Evaluating code
>> organizer_tasks
>> Nov 16 09:42:03 nub mh[3542]: 11/16/21 09:42:03 AM Family turned on
>> Nov 16 09:42:03 nub mh[3542]: 11/16/21 09:42:03 AM [Insteon::BaseObject]
>> $yardlight2::set(OFF, )
>> Nov 16 09:42:03 nub mh[3542]: 11/16/21 09:42:03 AM [Insteon::BaseObject]
>> $yardlight3::set(OFF, )
>>
>>
>> print.log
>> 11/16/21 09:39:58 AM [Insteon_PLM] DEBUG2: Sending obj=$garage_iolinc;
>> command=set_operating_flags; extra=06 incurred delay of 3.45 seconds;
>> starting hop-count: 3
>> 11/16/21 09:39:58 AM [Insteon_PLM] DEBUG3: Sending  PLM raw data:
>> 0262348b560f2006
>> 11/16/21 09:39:58 AM [Insteon_PLM] DEBUG4:
>>          PLM Command: (0262) insteon_send
>>               To Address: 34:8b:56
>>            Message Flags: 0f
>>                 Message Type: (000) Direct Message
>>               Message Length: (0) Standard Length
>>                    Hops Left: 3
>>                     Max Hops: 3
>>          Insteon Message: 2006
>>                        Cmd 1: (20) Set Operating Flags
>>                        Cmd 2: (06) Deveice Dependent
>>
>> 11/16/21 09:40:00 AM [Insteon::BaseMessage] WARN: now resending
>> obj=$garage_iolinc; command=set_operating_flags; extra=06 after 3
>> attempts.
>> 11/16/21 09:40:00 AM [Insteon_PLM] DEBUG2: Sending obj=$garage_iolinc;
>> command=set_operating_flags; extra=06 incurred delay of 5.49 seconds;
>> starting hop-count: 3
>> 11/16/21 09:40:00 AM [Insteon_PLM] DEBUG3: Sending  PLM raw data:
>> 0262348b560f2006
>> 11/16/21 09:40:00 AM [Insteon_PLM] DEBUG4:
>>          PLM Command: (0262) insteon_send
>>               To Address: 34:8b:56
>>            Message Flags: 0f
>>                 Message Type: (000) Direct Message
>>               Message Length: (0) Standard Length
>>                    Hops Left: 3
>>                     Max Hops: 3
>>          Insteon Message: 2006
>>                        Cmd 1: (20) Set Operating Flags
>>                        Cmd 2: (06) Deveice Dependent
>>
>> 11/16/21 09:40:02 AM [Insteon::BaseMessage] WARN: now resending
>> obj=$garage_iolinc; command=set_operating_flags; extra=06 after 4
>> attempts.
>> 11/16/21 09:40:02 AM [Insteon_PLM] DEBUG2: Sending obj=$garage_iolinc;
>> command=set_operating_flags; extra=06 incurred delay of 7.51 seconds;
>> starting hop-count: 3
>> 11/16/21 09:40:02 AM [Insteon_PLM] DEBUG3: Sending  PLM raw data:
>> 0262348b560f2006
>> 11/16/21 09:40:02 AM [Insteon_PLM] DEBUG4:
>>          PLM Command: (0262) insteon_send
>>               To Address: 34:8b:56
>>            Message Flags: 0f
>>                 Message Type: (000) Direct Message
>>               Message Length: (0) Standard Length
>>                    Hops Left: 3
>>                     Max Hops: 3
>>          Insteon Message: 2006
>>                        Cmd 1: (20) Set Operating Flags
>>                        Cmd 2: (06) Deveice Dependent
>>
>> 11/16/21 09:40:04 AM [Insteon::BaseInterface] WARN: number of retries
>> (5) for obj=$garage_iolinc; command=set_operating_flags; extra=06
>> exceeds limit.  Now moving on...
>> 11/16/21 09:40:04 AM [Insteon_PLM] DEBUG2: Sending obj=$PLM;
>> interface_data= incurred delay of 9.37 seconds; starting hop-count: ?
>> 11/16/21 09:40:04 AM [Insteon_PLM] DEBUG3: Sending  PLM raw data: 0260
>> 11/16/21 09:40:04 AM [Insteon_PLM] DEBUG4:
>>          PLM Command: (0260) plm_info
>>
>> 11/16/21 09:42:03 AM ---------- Restart ----------
>> 11/16/21 09:42:03 AM [Insteon_PLM] serial:/dev/ttyUSB0:19200
>> 11/16/21 09:42:03 AM [IA7_Collection_Updater] : Starting
>> 11/16/21 09:42:03 AM [IA7_Collection_Updater] : Reviewing
>> ./../data/web/collections.json to current version 1.4
>> 11/16/21 09:42:03 AM [IA7_Collection_Updater] : Finished
>> 11/16/21 09:42:03 AM Perl @INC contains: /opt/mista/code/common/,
>> ./../code/common, /opt/mista/mh/bin/../lib,
>> /opt/mista/mh/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, .
>> 11/16/21 09:42:03 AM Reading /opt/mista/mh.mine.ini and mh.ini
>> 11/16/21 09:42:03 AM Reading 1 .mht table files: insteon.mht
>> 11/16/21 09:42:03 AM Translating insteon.mht ->
>> /opt/mista/code/common//insteon.mhp
>> 11/16/21 09:42:03 AM Initialized read_table_A.pl
>> 11/16/21 09:42:03 AM Reading 16 code files
>> 11/16/21 09:42:03 AM Evaluating user code
>> 11/16/21 09:42:03 AM [Insteon_PLM] 2412[US] using serial,
>> serial_port=/dev/ttyUSB0
>> 11/16/21 09:42:03 AM [Insteon] Setting up initialization hooks
>> 11/16/21 09:42:03 AM [Insteon_PLM] setting default xmit delay to: 0.15
>> 11/16/21 09:42:03 AM [Insteon_PLM] setting x10 xmit delay to: 0.5
>> 11/16/21 09:42:03 AM FUNCTION: set_volume_pre_hook
>> 11/16/21 09:42:03 AM running: play ./../sounds/sound_click1.wav
>>
>> 11/16/21 09:42:03 AM IA7 Speech Notifications enabled
>> 11/16/21 09:42:03 AM [Insteon] DEBUG4 Checking aldb version of all
>> devices
>> 11/16/21 09:42:03 AM [Insteon] DEBUG4 Checking aldb version for
>> $porchlight2 (1 of 7)
>> 11/16/21 09:42:03 AM [Insteon::BaseDevice] DEBUG4: aldb_version is I1
>> but device is I2CS.  Remapping aldb version to I2
>> 11/16/21 09:42:03 AM [Insteon] DEBUG4 Checking aldb version for
>> $yardlight3 (2 of 7)
>> 11/16/21 09:42:03 AM [Insteon::BaseDevice] DEBUG4: aldb_version is I1
>> but device is I2CS.  Remapping aldb version to I2
>> 11/16/21 09:42:03 AM [Insteon] DEBUG4 Checking aldb version for
>> $yardlight2 (3 of 7)
>> 11/16/21 09:42:03 AM [Insteon::BaseDevice] DEBUG4: aldb_version is I1
>> but device is I2CS.  Remapping aldb version to I2
>> 11/16/21 09:42:03 AM [Insteon] DEBUG4 Checking aldb version for
>> $garage_in (4 of 7)
>> 11/16/21 09:42:03 AM [Insteon::BaseDevice] DEBUG4: aldb_version is I1
>> but device is I2CS.  Remapping aldb version to I2
>> 11/16/21 09:42:03 AM [Insteon] DEBUG4 Checking aldb version for $famroom
>> (5 of 7)
>> 11/16/21 09:42:03 AM [Insteon::BaseDevice] DEBUG4: aldb_version is I1
>> but device is I2CS.  Remapping aldb version to I2
>> 11/16/21 09:42:03 AM [Insteon] DEBUG4 Checking aldb version for
>> $porchlight1 (6 of 7)
>> 11/16/21 09:42:03 AM [Insteon::BaseDevice] DEBUG4: aldb_version is I1
>> but device is I2CS.  Remapping aldb version to I2
>> 11/16/21 09:42:03 AM [Insteon] DEBUG4 Checking aldb version for
>> $garage_iolinc (7 of 7)
>> 11/16/21 09:42:03 AM [Insteon::BaseDevice] DEBUG4: aldb_version is I1
>> but device is I2CS.  Remapping aldb version to I2
>> 11/16/21 09:42:03 AM [Insteon] DEBUG4 Checking aldb version of all
>> devices completed
>> 11/16/21 09:42:03 AM [Insteon::BaseMessage] WARN: now resending
>> obj=$garage_iolinc; command=set_operating_flags; extra=06 after 1
>> attempts.
>> 11/16/21 09:42:03 AM [Insteon::BaseMessage] WARN: now resending
>> obj=$garage_iolinc; command=set_operating_flags; extra=06 after 2
>> attempts.
>> 11/16/21 09:42:03 AM [Insteon::BaseMessage] WARN: now resending
>> obj=$garage_iolinc; command=set_operating_flags; extra=06 after 3
>> attempts.
>> 11/16/21 09:42:03 AM [Insteon::BaseMessage] WARN: now resending
>> obj=$garage_iolinc; command=set_operating_flags; extra=06 after 4
>> attempts.
>> 11/16/21 09:42:03 AM [Insteon::BaseInterface] WARN: number of retries
>> (5) for obj=$garage_iolinc; command=set_operating_flags; extra=06
>> exceeds limit.  Now moving on...
>> 11/16/21 09:42:03 AM [Insteon::BaseMessage] WARN: now resending
>> obj=$PLM; interface_data= after 1 attempts.
>> 11/16/21 09:42:03 AM [Insteon::BaseMessage] WARN: now resending
>> obj=$PLM; interface_data= after 2 attempts.
>> 11/16/21 09:42:03 AM [Insteon::BaseMessage] WARN: now resending
>> obj=$PLM; interface_data= after 3 attempts.
>> 11/16/21 09:42:03 AM [Insteon] DEBUG4 Initializing thermostat versions
>> 11/16/21 09:42:03 AM Generating Voice commands for all Insteon objects
>> 11/16/21 09:42:03 AM Rereading .menu code files.
>> 11/16/21 09:42:03 AM Organizer: Calendar matches target schema and does
>> not require upgrading
>> 11/16/21 09:42:03 AM Organizer: Todo matches target schema and does not
>> require upgrading
>> 11/16/21 09:42:03 AM Organizer: Reading updated organizer calendar
>> file now
>> 11/16/21 09:42:03 AM Evaluating code organizer_events
>> 11/16/21 09:42:03 AM Organizer: Reading updated organizer todo file
>> 11/16/21 09:42:03 AM Evaluating code organizer_tasks
>> 11/16/21 09:42:03 AM Family turned on
>> 11/16/21 09:42:03 AM [Insteon::BaseObject] $yardlight2::set(OFF, )
>> 11/16/21 09:42:03 AM [Insteon::BaseObject] $yardlight3::set(OFF, )
>>
>>
>> ________________________________________________________
>> To unsubscribe from this list, go to:
>> https://lists.sourceforge.net/lists/listinfo/misterhouse-users
>>
>
>
>
> ________________________________________________________
> To unsubscribe from this list, go to:https://lists.sourceforge.net/lists/listinfo/misterhouse-users
>

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