Delay when executing a ssh command

Configuration
1

Hello !

I have two command_line switch :

  - platform: command_line
    switches:
      alarm_wait:
        command_on: ssh -i /config/ssh_keys/id_rsa -o UserKnownHostsFile=/dev/null -o StrictHostKeyChecking=no [email protected] /home/pi/alarm_wait.sh
        friendly_name: alarm_wait

  - platform: command_line
    switches:
      kill_alarm_wait:
        command_on: ssh -i /config/ssh_keys/id_rsa -o UserKnownHostsFile=/dev/null -o StrictHostKeyChecking=no [email protected] /home/pi/kill_alarm_wait.sh
        friendly_name: kill_alarm_wait

These are used for my alarm:

alarm_wait is triggered for the pending phase (it play a song like "You have twenty seconds before alarm is triggered, you have ten seconds before alarm is triggered etc… )

kill_alarm_wait is triggered when alarm is disabled (it stop the player who play the song)

These two scripts are hosted on a dedicated Raspberry Pi

When used in HA, the first script(alarm_wait) is well executed (without any delay) for the pending phase. But, the second (kill_alarm_wait) is executed with a big delay (something like 10 seconds…)

If I launch these script from another machine (another pi for example), they works well : alarm_wait AND kill_alarm_wait are triggered with no delay. So, for me, issue is on HA but I don’t understand why the first script is executed with no delay, and the other one has a huge delay

alarm_wait.sh :

#!/bin/sh
/usr/bin/aplay /home/pi/alarm_wait2.wav

kill_alarm_wait.sh

#!/bin/sh
/usr/bin/killall /usr/bin/aplay

Thanks for your help !

2

What timings do you see on the raspberry pi’s ssh server log? (You may want to enable verbose logging).

3

Here is ssh logs when executing using HA automations :

Feb 1 14:10:43 NadHAT sshd[9112]: Accepted publickey for pi from 192.168.2.189 port 44050 ssh2: RSA SHA256:blablablabla
Feb 1 14:10:43 NadHAT sshd[9112]: pam_unix(sshd:session): session opened for user pi by (uid=0)
Feb 1 14:10:43 NadHAT systemd-logind[381]: New session c534 of user pi.
Feb 1 14:10:58 NadHAT sshd[9112]: pam_unix(sshd:session): session closed for user pi
Feb 1 14:10:58 NadHAT systemd-logind[381]: Session c534 logged out. Waiting for processes to exit.
Feb 1 14:10:58 NadHAT sshd[9128]: Accepted publickey for pi from 192.168.2.189 port 44052 ssh2: RSA SHA256:blablablabla
Feb 1 14:10:58 NadHAT sshd[9128]: pam_unix(sshd:session): session opened for user pi by (uid=0)
Feb 1 14:10:58 NadHAT systemd-logind[381]: New session c535 of user pi.
Feb 1 14:10:58 NadHAT systemd-logind[381]: Removed session c534.
Feb 1 14:10:58 NadHAT sshd[9137]: Received disconnect from 192.168.2.189 port 44052:11: disconnected by user
Feb 1 14:10:58 NadHAT sshd[9137]: Disconnected from user pi 192.168.2.189 port 44052
Feb 1 14:10:58 NadHAT sshd[9128]: pam_unix(sshd:session): session closed for user pi
Feb 1 14:10:58 NadHAT systemd-logind[381]: Session c535 logged out. Waiting for processes to exit.
Feb 1 14:10:58 NadHAT systemd-logind[381]: Removed session c535.

And here is ssh logs when executing scripts from another pi (ssh [email protected] /home/pi/alarm_wait.sh and ssh [email protected] /home/pi/kill_alarm_wait.sh) :

Feb 1 14:11:25 NadHAT sshd[9150]: Accepted publickey for pi from 192.168.2.103 port 50314 ssh2: RSA SHA256:blablablabla
Feb 1 14:11:25 NadHAT sshd[9150]: pam_unix(sshd:session): session opened for user pi by (uid=0)
Feb 1 14:11:25 NadHAT systemd-logind[381]: New session c536 of user pi.
Feb 1 14:11:35 NadHAT sshd[9164]: Accepted publickey for pi from 192.168.2.103 port 50338 ssh2: RSA SHA256:blablablabla
Feb 1 14:11:35 NadHAT sshd[9164]: pam_unix(sshd:session): session opened for user pi by (uid=0)
Feb 1 14:11:35 NadHAT systemd-logind[381]: New session c537 of user pi.
Feb 1 14:11:35 NadHAT sshd[9173]: Received disconnect from 192.168.2.103 port 50338:11: disconnected by user
Feb 1 14:11:35 NadHAT sshd[9173]: Disconnected from user pi 192.168.2.103 port 50338
Feb 1 14:11:35 NadHAT sshd[9164]: pam_unix(sshd:session): session closed for user pi
Feb 1 14:11:35 NadHAT systemd-logind[381]: Session c537 logged out. Waiting for processes to exit.
Feb 1 14:11:35 NadHAT systemd-logind[381]: Removed session c537.
Feb 1 14:11:36 NadHAT sshd[9159]: Received disconnect from 192.168.2.103 port 50314:11: disconnected by user
Feb 1 14:11:36 NadHAT sshd[9159]: Disconnected from user pi 192.168.2.103 port 50314
Feb 1 14:11:36 NadHAT sshd[9150]: pam_unix(sshd:session): session closed for user pi
Feb 1 14:11:36 NadHAT systemd-logind[381]: Session c536 logged out. Waiting for processes to exit.
Feb 1 14:11:36 NadHAT systemd-logind[381]: Removed session c536.

It looks like when launching scripts from HA, it waits to close the session BEFORE to accept a new session. And the delay is 15 seconds (from 14:10:43 to 14:10:58)

Because when launching scripts from another pi, the two session are opened without wait for the session to be closed

Scenario : execute “alarm_wait”, wait 10 seconds and execute “kill_alarm_wait”
Infos :
192.168.2.189 is HA
192.168.2.120 is the pi where scripts are hosted
192.168.2.103 is the pi used to execute scripts on 192.168.2.120 (to test)

4

Really strange…If I use shell_comand instead of command_line : no more delay. Primary session must not be closed before the second can be started :

Feb 2 08:46:13 NadHAT sshd[6489]: Accepted publickey for pi from 192.168.2.189 port 55490 ssh2: RSA SHA256:blablabla
Feb 2 08:46:13 NadHAT sshd[6489]: pam_unix(sshd:session): session opened for user pi by (uid=0)
Feb 2 08:46:13 NadHAT systemd-logind[381]: New session c606 of user pi.
Feb 2 08:46:24 NadHAT sshd[6502]: Accepted publickey for pi from 192.168.2.189 port 55492 ssh2: RSA SHA256:blablabla
Feb 2 08:46:24 NadHAT sshd[6502]: pam_unix(sshd:session): session opened for user pi by (uid=0)
Feb 2 08:46:24 NadHAT systemd-logind[381]: New session c607 of user pi.
Feb 2 08:46:24 NadHAT sudo: pi : TTY=unknown ; PWD=/home/pi ; USER=root ; COMMAND=/usr/bin/killall aplay
Feb 2 08:46:24 NadHAT sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 2 08:46:24 NadHAT sudo: pam_unix(sudo:session): session closed for user root
Feb 2 08:46:24 NadHAT sshd[6511]: Received disconnect from 192.168.2.189 port 55492:11: disconnected by user
Feb 2 08:46:24 NadHAT sshd[6511]: Disconnected from user pi 192.168.2.189 port 55492
Feb 2 08:46:24 NadHAT sshd[6502]: pam_unix(sshd:session): session closed for user pi
Feb 2 08:46:24 NadHAT systemd-logind[381]: Session c607 logged out. Waiting for processes to exit.
Feb 2 08:46:24 NadHAT systemd-logind[381]: Removed session c607.
Feb 2 08:46:24 NadHAT sshd[6498]: Received disconnect from 192.168.2.189 port 55490:11: disconnected by user
Feb 2 08:46:24 NadHAT sshd[6498]: Disconnected from user pi 192.168.2.189 port 55490
Feb 2 08:46:24 NadHAT sshd[6489]: pam_unix(sshd:session): session closed for user pi
Feb 2 08:46:24 NadHAT systemd-logind[381]: Session c606 logged out. Waiting for processes to exit.
Feb 2 08:46:24 NadHAT systemd-logind[381]: Removed session c606.

1 Like