Command line switch nightmares

Hello!
I have little problem with switches. I have a config:

  - platform: command_line
    switches:
      tv_backlight:
        command_on: '/home/homeassistant/.homeassistant/external_scripts/backlight.sh start'
        command_off: '/home/homeassistant/.homeassistant/external_scripts/backlight.sh stop'
        command_state: '/home/homeassistant/.homeassistant/external_scripts/backlight.sh status'
        value_template: '{{ value == "Running." }}'
      ambilight:
        command_on: '/home/homeassistant/.homeassistant/external_scripts/ambilight.sh start'
        command_off: '/home/homeassistant/.homeassistant/external_scripts/ambilight.sh stop'
        command_state: '/home/homeassistant/.homeassistant/external_scripts/ambilight.sh status'
        value_template: '{{ value == "Running." }}'

Every script Works from command line as root, or as home assistant user. But if I toggle the switch on dashboard, the script does not starts. I found these in debug log:

17-03-19 16:16:28 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 139636547204208: Received {'type': 'call_service', 'domain': 'homeassistant', 'service_data': {'entity_id': 'switch.ambilight'}, 'id': 9, 'service': 'turn_on'}
17-03-19 16:16:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service_data=entity_id=switch.ambilight, service_call_id=139636523327728-9, service=turn_on>
17-03-19 16:16:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service_data=entity_id=['switch.ambilight'], service_call_id=139636523327728-10, service=turn_on>
17-03-19 16:16:28 INFO (Thread-10) [homeassistant.components.switch.command_line] Running command: /home/homeassistant/.homeassistant/external_scripts/ambilight.sh start
17-03-19 16:16:28 ERROR (Thread-10) [homeassistant.components.switch.command_line] Command failed: /home/homeassistant/.homeassistant/external_scripts/ambilight.sh start
17-03-19 16:16:28 INFO (Thread-3) [homeassistant.components.switch.command_line] Running state command: /home/homeassistant/.homeassistant/external_scripts/ambilight.sh status
17-03-19 16:16:28 ERROR (Thread-3) [homeassistant.components.switch.command_line] Command failed: /home/homeassistant/.homeassistant/external_scripts/ambilight.sh status

So command failed… Why? How can I debug it?

Another switch:

17-03-19 16:20:02 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 139636547204208: Received {'type': 'call_service', 'domain': 'homeassistant', 'service_data': {'entity_id': 'switch.tv_backlight'}, 'id': 11, 'service': 'turn_on'}
17-03-19 16:20:02 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service_data=entity_id=switch.tv_backlight, service_call_id=139636523327728-13, service=turn_on>
17-03-19 16:20:02 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service_data=entity_id=['switch.tv_backlight'], service_call_id=139636523327728-14, service=turn_on>
17-03-19 16:20:02 INFO (Thread-6) [homeassistant.components.switch.command_line] Running command: /home/homeassistant/.homeassistant/external_scripts/backlight.sh start
17-03-19 16:20:02 INFO (Thread-9) [homeassistant.components.switch.command_line] Running state command: /home/homeassistant/.homeassistant/external_scripts/backlight.sh status
17-03-19 16:20:02 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state switch.tv_backlight=on; friendly_name=tv_backlight @ 2017-03-19T16:20:02.935382+01:00>, old_state=<state switch.tv_backlight=off; friendly_name=tv_backlight @ 2017-03-19T16:19:56.049007+01:00>, entity_id=switch.tv_backlight>
17-03-19 16:20:02 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 139636547681696: Sending {'type': 'event', 'event': {'data': {'new_state': <state switch.tv_backlight=on; friendly_name=tv_backlight @ 2017-03-19T16:20:02.935382+01:00>, 'old_state': <state switch.tv_backlight=off; friendly_name=tv_backlight @ 2017-03-19T16:19:56.049007+01:00>, 'entity_id': 'switch.tv_backlight'}, 'time_fired': datetime.datetime(2017, 3, 19, 15, 20, 2, 935501, tzinfo=<UTC>), 'event_type': 'state_changed', 'origin': 'LOCAL'}, 'id': 2}
17-03-19 16:20:02 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 139636547204208: Sending {'type': 'event', 'event': {'data': {'new_state': <state switch.tv_backlight=on; friendly_name=tv_backlight @ 2017-03-19T16:20:02.935382+01:00>, 'old_state': <state switch.tv_backlight=off; friendly_name=tv_backlight @ 2017-03-19T16:19:56.049007+01:00>, 'entity_id': 'switch.tv_backlight'}, 'time_fired': datetime.datetime(2017, 3, 19, 15, 20, 2, 935501, tzinfo=<UTC>), 'event_type': 'state_changed', 'origin': 'LOCAL'}, 'id': 2}
17-03-19 16:20:02 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139636523327728-14>
17-03-19 16:20:02 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state group.all_switches=on; order=5, auto=True, hidden=True, friendly_name=all switches, entity_id=('switch.tv_backlight', 'switch.ambilight') @ 2017-03-19T16:20:02.946845+01:00>, old_state=<state group.all_switches=off; order=5, auto=True, hidden=True, friendly_name=all switches, entity_id=('switch.tv_backlight', 'switch.ambilight') @ 2017-03-19T16:19:56.065035+01:00>, entity_id=group.all_switches>
17-03-19 16:20:02 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 139636547681696: Sending {'type': 'event', 'event': {'data': {'new_state': <state group.all_switches=on; order=5, auto=True, hidden=True, friendly_name=all switches, entity_id=('switch.tv_backlight', 'switch.ambilight') @ 2017-03-19T16:20:02.946845+01:00>, 'old_state': <state group.all_switches=off; order=5, auto=True, hidden=True, friendly_name=all switches, entity_id=('switch.tv_backlight', 'switch.ambilight') @ 2017-03-19T16:19:56.065035+01:00>, 'entity_id': 'group.all_switches'}, 'time_fired': datetime.datetime(2017, 3, 19, 15, 20, 2, 946920, tzinfo=<UTC>), 'event_type': 'state_changed', 'origin': 'LOCAL'}, 'id': 2}
17-03-19 16:20:02 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 139636547204208: Sending {'type': 'event', 'event': {'data': {'new_state': <state group.all_switches=on; order=5, auto=True, hidden=True, friendly_name=all switches, entity_id=('switch.tv_backlight', 'switch.ambilight') @ 2017-03-19T16:20:02.946845+01:00>, 'old_state': <state group.all_switches=off; order=5, auto=True, hidden=True, friendly_name=all switches, entity_id=('switch.tv_backlight', 'switch.ambilight') @ 2017-03-19T16:19:56.065035+01:00>, 'entity_id': 'group.all_switches'}, 'time_fired': datetime.datetime(2017, 3, 19, 15, 20, 2, 946920, tzinfo=<UTC>), 'event_type': 'state_changed', 'origin': 'LOCAL'}, 'id': 2}
17-03-19 16:20:02 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139636523327728-13>
17-03-19 16:20:02 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 139636547204208: Sending {'type': 'result', 'result': None, 'id': 11, 'success': True}

Yeas, it Works! Wow! When I try to turn off this switch:

17-03-19 16:23:42 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 139636547681696: Received {'type': 'call_service', 'domain': 'homeassistant', 'service_data': {'entity_id': 'switch.tv_backlight'}, 'id': 9, 'service': 'turn_off'}
17-03-19 16:23:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service_data=entity_id=switch.tv_backlight, service_call_id=139636523327728-15, service=turn_off>
17-03-19 16:23:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service_data=entity_id=['switch.tv_backlight'], service_call_id=139636523327728-16, service=turn_off>
17-03-19 16:23:42 INFO (Thread-11) [homeassistant.components.switch.command_line] Running command: /home/homeassistant/.homeassistant/external_scripts/backlight.sh stop
17-03-19 16:23:42 INFO (Thread-5) [homeassistant.components.switch.command_line] Running state command: /home/homeassistant/.homeassistant/external_scripts/backlight.sh status
17-03-19 16:23:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139636523327728-16>
17-03-19 16:23:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139636523327728-15>
17-03-19 16:23:42 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 139636547681696: Sending {'type': 'result', 'result': None, 'id': 9, 'success': True}

There is no error. But the switch remains turned on, HA didn’t run the command.

So my problem in a nutshell:

-switch named ambilight does not works. I can’t start, stop or query status.
-switch named tv_backlight does not works. I can start or query state, but I can’t turn off.

What I missed? How can I debug it?

Do your scripts include outside resources/dependencies? Does your HA install run inside a virtual environment (like all-in-one does)? One more thing to check is that - if they do - that you’ve installed the dependency inside the venv. You kind of need to think about the venv as it’s own machine.

So, test your commands (from the shell) while sudo’ed to the HA user and source the venv. For my install, this enters the venv:

source /srv/hass/hass_venv/bin/activate

your path may vary.