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

You can confirm you have something like this to get the startup log:

debug=startup

log_file=/var/log/misterhouse.log


On 11/19/21 22:41, hoodcanaljim wrote:
>
> 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
>

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