Automation fired multiple times for unknown reason

kwetiaw · April 21, 2016, 3:50am

I am using RPi3 and Latest HASS

In my automation, the switch triggers a simple bash script that send signals to activate an RF power switch

Here’s my switch config

switch:
  platform: command_switch
  switches:
    Lampu Ruang Tamu:
      oncmd: "sudo /var/opt/homeassistant/rfoutlet/RF1ON.sh"
      offcmd: "sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh"

Here’s my automation

- alias: 'RULE 2 - Turn on light when sun sets'
  trigger:
    platform: sun
    event: sunset
    offset: "-00:15:00"
  action:
    service: switch.turn_on
    entity_id: switch.lampu_ruang_tamu
- alias: 'RULE 2 Living Room Light OFF at 23:00pm'
  trigger:
    - platform: time
      hours: 11
      minutes: 55
  action:
    service: switch.turn_off
    entity_id: switch.lampu_ruang_tamu

Now the funny thing here is, when I use the switch individually without automation, it fired once.

16-04-21 13:46:01 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_on, domain=homeassistant, service_call_id=1979121168-63, service_data=entity_id=switch.lampu_ruang_tamu>
16-04-21 13:46:01 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_on, domain=switch, service_call_id=1979121168-64, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 13:46:01 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1ON.sh
16-04-21 13:46:01 homeassistant.core: Bus:Handling <Event state_changed[L]: new_state=<state switch.lampu_ruang_tamu=on; friendly_name=Lampu Ruang Tamu @ 13:46:01 21-04-2016>, entity_id=switch.lampu_ruang_tamu, old_state=<state switch.lampu_ruang_tamu=off; friendly_name=Lampu Ruang Tamu @ 11:55:00 21-04-2016>>
16-04-21 13:46:01 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-64>

But when put in automation, it fired multiple times.

16-04-21 11:55:00 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm
16-04-21 11:55:00 homeassistant.components.device_tracker.ddwrt: Checking ARP
16-04-21 11:55:00 homeassistant.core: Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=RULE 2 Living Room Light OFF at 23:00pm>
16-04-21 11:55:00 urllib3.connectionpool: Starting new HTTP connection (1): 10.0.0.1
16-04-21 11:55:00 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_off, domain=switch, service_call_id=1979121168-3, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 11:55:00 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh
16-04-21 11:55:00 homeassistant.core: Bus:Handling <Event state_changed[L]: new_state=<state switch.lampu_ruang_tamu=off; friendly_name=Lampu Ruang Tamu @ 11:55:00 21-04-2016>, entity_id=switch.lampu_ruang_tamu, old_state=<state switch.lampu_ruang_tamu=on; friendly_name=Lampu Ruang Tamu @ 11:54:13 21-04-2016>>
16-04-21 11:55:00 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-3>
16-04-21 11:55:00 homeassistant.core: Bus:Handling <Event state_changed[L]: new_state=<state group.all_switches=off; order=0, auto=True, entity_id=('switch.vaporiser', 'switch.lampu_ruang_tamu', 'switch.debuan_server', 'switch.lampu_malam', 'switch.plex_server'), hidden=True, friendly_name=all switches @ 11:55:00 21-04-2016>, entity_id=group.all_switches, old_state=<state group.all_switches=on; order=0, auto=True, entity_id=('switch.vaporiser', 'switch.lampu_ruang_tamu', 'switch.debuan_server', 'switch.lampu_malam', 'switch.plex_server'), hidden=True, friendly_name=all switches @ 11:54:13 21-04-2016>>
16-04-21 11:55:00 homeassistant.core: Bus:Handling <Event state_changed[L]: new_state=<state group.lampu=off; order=2, entity_id=('switch.lampu_ruang_tamu', 'switch.lampu_malam'), friendly_name=lampu @ 11:55:00 21-04-2016>, entity_id=group.lampu, old_state=<state group.lampu=on; order=2, entity_id=('switch.lampu_ruang_tamu', 'switch.lampu_malam'), friendly_name=lampu @ 11:54:13 21-04-2016>>
16-04-21 11:55:01 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm
16-04-21 11:55:01 homeassistant.core: Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=RULE 2 Living Room Light OFF at 23:00pm>
16-04-21 11:55:01 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_off, domain=switch, service_call_id=1979121168-4, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 11:55:01 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh
16-04-21 11:55:02 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-4>
16-04-21 11:55:02 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm
16-04-21 11:55:02 homeassistant.core: Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=RULE 2 Living Room Light OFF at 23:00pm>
16-04-21 11:55:02 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_off, domain=switch, service_call_id=1979121168-5, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 11:55:02 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh
16-04-21 11:55:03 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-5>
16-04-21 11:55:03 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm
16-04-21 11:55:03 homeassistant.core: Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=RULE 2 Living Room Light OFF at 23:00pm>
16-04-21 11:55:03 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_off, domain=switch, service_call_id=1979121168-6, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 11:55:03 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh
16-04-21 11:55:03 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-6>
16-04-21 11:55:04 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm
16-04-21 11:55:04 homeassistant.core: Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=RULE 2 Living Room Light OFF at 23:00pm>
16-04-21 11:55:04 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_off, domain=switch, service_call_id=1979121168-7, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 11:55:04 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh
16-04-21 11:55:04 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-7>
16-04-21 11:55:05 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm
16-04-21 11:55:05 homeassistant.core: Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=RULE 2 Living Room Light OFF at 23:00pm>
16-04-21 11:55:05 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_off, domain=switch, service_call_id=1979121168-8, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 11:55:05 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh
16-04-21 11:55:05 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-8>
16-04-21 11:55:06 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm
16-04-21 11:55:06 homeassistant.core: Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=RULE 2 Living Room Light OFF at 23:00pm>
16-04-21 11:55:06 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_off, domain=switch, service_call_id=1979121168-9, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 11:55:06 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh
16-04-21 11:55:06 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-9>
16-04-21 11:55:07 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm
16-04-21 11:55:07 homeassistant.core: Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=RULE 2 Living Room Light OFF at 23:00pm>
16-04-21 11:55:07 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_off, domain=switch, service_call_id=1979121168-10, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 11:55:07 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh
16-04-21 11:55:07 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-10>
16-04-21 11:55:08 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm
16-04-21 11:55:08 homeassistant.core: Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=RULE 2 Living Room Light OFF at 23:00pm>
16-04-21 11:55:08 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_off, domain=switch, service_call_id=1979121168-11, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 11:55:08 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh
16-04-21 11:55:08 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-11>
16-04-21 11:55:09 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm
16-04-21 11:55:09 homeassistant.core: Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=RULE 2 Living Room Light OFF at 23:00pm>
16-04-21 11:55:09 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_off, domain=switch, service_call_id=1979121168-12, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 11:55:09 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh
16-04-21 11:55:09 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-12>
16-04-21 11:55:10 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm
16-04-21 11:55:10 homeassistant.core: Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=RULE 2 Living Room Light OFF at 23:00pm>
16-04-21 11:55:10 homeassistant.core: Bus:Handling <Event call_service[L]: service=turn_off, domain=switch, service_call_id=1979121168-13, service_data=entity_id=['switch.lampu_ruang_tamu']>
16-04-21 11:55:10 homeassistant.components.switch.command_switch: Running command: sudo /var/opt/homeassistant/rfoutlet/RF1OFF.sh
16-04-21 11:55:10 homeassistant.core: Bus:Handling <Event service_executed[L]: service_call_id=1979121168-13>
16-04-21 11:55:11 homeassistant.components.automation: Executing RULE 2 Living Room Light OFF at 23:00pm

I’m puzzled and unsure why this happens, any pointers anyone?

Thanks and appreciate the help.

photo64 · April 21, 2016, 11:58am

Looks like it is triggering every second, could it be as simple as adding “Seconds: 00” to your trigger platform?

kwetiaw · April 22, 2016, 8:20am

hey @photo64 that seems to do the trick. i would never figure it out for sure. i thought seconds are optional and hence i didnt even bother putting it in.

thanks heaps