'enableAutoOff' Switches Spam Homebridge Logs

[mitch7391]

Describe the bug My switches with "enableAutoOff": true that I use for automations seem to add a lot of log entries; here is just one:

[08/02/2021, 20:29:59] [Broadlink RM] Light Down getSwitchState: false
[08/02/2021, 20:29:59] [Broadlink RM] Light Down setSwitchState: true
[08/02/2021, 20:29:59] [Broadlink RM] Light Down sendHex (192.168.0.155; 34:ea:34:99:f1:28) b2000e010434040504040504040d100c2a25100c2a0c2925110c29251125100c2a0d1107190461080404290c290a2c041d0404041025110c290d0001960c2a0b2a04042f0d291d04061025110c2926100c2a0c2925100d29251026100c2926100d280d290c2a0c290d28261026100c290d0001960c2a0c290c2a0c29261025100c2a25100d290c2a25100c2a251026100c2a25100c2a0c290d290c2a0c29251125100d280d0001960d290c290d290d29251026100c2926100c290d2925110c29261025100d2925110c290c290d290c2a0c29261025100d290d0001960c290d290c290d29251026100c2926100c2a0c291c0406110c29261025100c2a25100d290c2a0c290c290d29251125100c2a0c0005dc00000000000000000000
[08/02/2021, 20:29:59] [Broadlink RM] Light Down setSwitchState: (automatically turn off in 1 seconds)
[08/02/2021, 20:29:59] [Broadlink RM] Light Down getSwitchState: true
[08/02/2021, 20:29:59] [Broadlink RM] Light Down setSwitchState: true
[08/02/2021, 20:29:59] [Broadlink RM] Light Down setSwitchState: already true (no data sent - B)
[08/02/2021, 20:30:00] [Broadlink RM] Light Down getSwitchState: true
[08/02/2021, 20:30:00] [Broadlink RM] Light Down setSwitchState: true
[08/02/2021, 20:30:00] [Broadlink RM] Light Down setSwitchState: already true (no data sent - B)
[08/02/2021, 20:30:00] [Broadlink RM] Light Down setSwitchState: false

To Reproduce Happens every time the switch is activated.

Expected behaviour I would expect only one log entry.

Desktop (please complete the following information):

• OS: Windows 10
• Browser: Mozilla Firefox
• Version: Latest stable

Smartphone (please complete the following information):

• Device: iPhone 12 Pro
• OS: iOS14.4
• Browser: Safari
• Version: Latest stable

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mitch7391]

Hey @kiwi-cam I am still keen for this one if you get a chance :)

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mitch7391]

Commenting to keep this alive.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mitch7391]

@kiwi-cam im hoping this would be an easy one for you if you have the time :)

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mitch7391]

Bumping this again to keep it alive…

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mitch7391]

@kiwi-cam, is this something logLevel could sort out for me? I would like to keep it in my logs that the accessory was commanded; I just don’t want it doing what it is currently doing.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mitch7391]

Bumping to keep alive…

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mitch7391]

Bump

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[kiwi-cam]

Hi @mitch7391 Could you share your config for this accessory? It SHOULD only log that if your got logLevel set to debug or verbose. I'm curious what options you have that might impact that.

[mitch7391]

Hey @kiwi-cam, hopefully I am just doing something wrong, I really have not had to touch the config for any of these accessories since migrating over to you fork years ago; so maybe I am doing something 'outdated'.

I have cut my config down to just show one of these, I included the platform directives in there too in case you needed to see those.

        {
            "platform": "BroadlinkRM",
            "name": "Broadlink RM",
            "hideScanFrequencyButton": false,
            "hideLearnButton": false,
            "hideWelcomeMessage": true,
            "debug": false,
            "accessories": [
                {
                    "name": "Fan Down",
                    "type": "switch",
                    "data": "b2004e0109951d0b091e091f091e1d0b091e091f1d0a1d0b1d0a1d0b1d0a091f1d0a1d0b091e091f1d0a091f1d0b091e091f091e1d0a0a1e091f081f091f1c0b091f1d0a091f09951d0a091f091e091f1d0a091f091f1c0b1d0a1d0b1d0b1c0b091e1d0b1d0a091f091f1c0b091e1d0b091e091f091f1d0a091f091e091f091e1d0a0a1e1d0b091e09951d0b091f091e091e1d0b091e091f1d0b1c0b1d0b1d0a1d0b091e1d0b1c0b091f081f1d0b081f1d0b091e091f091e1d0b091e091f091e091f1c0c091e1c0b091f09951d0b091e091f091e1d0b091e091f1c0b1d0b1d0a1d0b1c0b091f1d0a1d0b091f081f1d0a091f1d0a091f091e091f1c0c081f091f091e091f1c0b091f1c0b091f09951c0b091f091e091f1c0b091f091e1d0b1d0a1d0b1d0b1c0b091f1c0b1d0a091f091e1d0b091f1c0b091e0a1e091f1c0b091f091e091f091e1d0b091e1d0b0820080005dc00000000000000000000",
                    "enableAutoOff": true,
                    "onDuration": 0.5
                }
            ],
            "_bridge": {
                "username": "XX:XX:XX:XX:XX:XX",
                "port": XXXXX
            }
        }

Hope this helps and let me know if you need anything else.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mitch7391]

Bump

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mitch7391]

Bump.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mitch7391]

Bump

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mitch7391]

@kiwi-cam any chance of looking at this one further?

[kiwi-cam]

Hi @mitch7391

I'm having a day where things just work for me. I haven't been able to recreate this issue.

                {
                    "name": "Dummy Switch",
                    "type": "switch",
                    "enableAutoOff": true,
                    "onDuration": 5,
                    "data": {
                        "on": "0000 006C ..... 0016 06FB",
                        "off": [
                            {
                                "data": "2600580000....000001",
                                "sendCount": 2,
                                "interval": 0.3
                            }
                        ]
                    }
                }

Jun 28 16:09:33 homebridge[31636]: [Broadlink RM] Dummy Switch setSwitchState: true
Jun 28 16:09:33 homebridge[31636]: [Broadlink RM] Dummy Switch setSwitchState: (automatically turn off in 5 seconds)
Jun 28 16:09:33 homebridge[31636]: [Broadlink RM] Dummy Switch sendHex (xxxx) 260046009....000000
Jun 28 16:09:38 homebridge[31636]: [Broadlink RM] Dummy Switch setSwitchState: false
Jun 28 16:09:38 homebridge[31636]: [Broadlink RM] Dummy Switch sendHex (xxxxx) 260058....000001
Jun 28 16:09:39 homebridge[31636]: [Broadlink RM] Dummy Switch sendHex (xxxx) 260058....000001

All I know is the output is coming from here: https://github.com/kiwi-cam/homebridge-broadlink-rm/blob/e2c9fa6ecdbb75c83943477fc0b23eb58f6875fb/base/accessory.js#L174

Which means, that for some reason your accessory is getting a logLevel of 1 or less, which is 'debug'.

As a workaround, you could add "logLevel": "warning" to your switch's config?

[kiwi-cam]

Another thought... do you have any automations triggered by your switch changing state? It could be something else monitoring the status of this switch.

[mitch7391]

Hey @kiwi-cam, thanks for testing this out... It seems when I first posted this issue back in 2021 it was based on a light I had and it was using an automation, the config I had sent you at a later stage was for a fan set up in a similar fashion but was not on an automation to send the value; since then I have got rid of the light but still have the fan and have not noticed that this does not happen with the fan... I should have realised this sooner, as it means this actually is not an issue for me anymore and had just assumed it was still an issue for me... So it sounds like you are right about it being an issue when automations are involved!

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.