why isn't the command exit log being shown when I pipe it through a bash function?

user_601147 0
Viewed 72

I want to create a script that runs multiple commands in parallel. I want it to exit all those commands when I git CTRL+C

The problem I am having is when I pipe the output of the first ping command to a bash function it does not print the exit logs. i.e. the logs containing "rtt min/avg/max/mdev = 6.808/6.855/6.906/0.040 ms"

How can I get this working? thanks :)

#!/bin/bash
trap terminate SIGINT
terminate(){
    echo "terminating started"
    pkill -SIGINT -P $$
    echo "terminating finished"
    exit
}

log () {
        sed -e "s/^/[$1]: /"
}

#the rest of your code goes here
ping 1.1.1.1 |& log "first_log" &
ping bbc.com  |& sed -e "s/^/[bbc_log]: /"&
wait

Here are the logs:

dewi@pop-os:~/tmp/bashtest$ bash bashtest
[first_log]: PING 1.1.1.1 (1.1.1.1) 56(84) bytes of data.
[first_log]: 64 bytes from 1.1.1.1: icmp_seq=1 ttl=56 time=9.37 ms
[first_log]: 64 bytes from 1.1.1.1: icmp_seq=2 ttl=56 time=9.31 ms
[bbc_log]: PING bbc.com(2a04:4e42::81 (2a04:4e42::81)) 56 data bytes
[bbc_log]: 64 bytes from 2a04:4e42::81 (2a04:4e42::81): icmp_seq=1 ttl=250 time=7.82 ms
[first_log]: 64 bytes from 1.1.1.1: icmp_seq=3 ttl=56 time=9.42 ms
[bbc_log]: 64 bytes from 2a04:4e42::81 (2a04:4e42::81): icmp_seq=2 ttl=250 time=6.32 ms
[first_log]: 64 bytes from 1.1.1.1: icmp_seq=4 ttl=56 time=9.32 ms
^C[bbc_log]: 64 bytes from 2a04:4e42::81: icmp_seq=3 ttl=250 time=6.66 ms
[bbc_log]:
[bbc_log]: --- bbc.com ping statistics ---
[bbc_log]: 3 packets transmitted, 3 received, 0% packet loss, time 2001ms
[bbc_log]: rtt min/avg/max/mdev = 6.317/6.930/7.816/0.641 ms
terminating started
terminating finished
dewi@pop-os:~/tmp/bashtest$

Mant thanks :)

Edit: here is a simpler version of the problem:

$ cat tst.sh
#!/usr/bin/env bash

log() {
    sed 's/^/[log]: /'
}

if [[ $1 == 1 ]]; then
    ping 1.1.1.1 2>&1 | sed 's/^/[log]: /' &
else
    ping 1.1.1.1 2>&1 | log &
fi

wait


$ ./tst.sh 1
[log]:
[log]: Pinging 1.1.1.1 with 32 bytes of data:
[log]: Reply from 1.1.1.1: bytes=32 time=20ms TTL=55
[log]:
[log]: Ping statistics for 1.1.1.1:
[log]:     Packets: Sent = 1, Received = 1, Lost = 0 (0% loss),
[log]: Approximate round trip times in milli-seconds:
[log]:     Minimum = 20ms, Maximum = 20ms, Average = 20ms
[log]: Control-C


$ ./tst.sh 2
[log]:
[log]: Pinging 1.1.1.1 with 32 bytes of data:
[log]: Reply from 1.1.1.1: bytes=32 time=59ms TTL=55

$

Both runs above were interrupted at about the same time. Why does the first version, calling sed directly, print the final stats from the ping while the 2nd version, calling sed through a function, doesn't?

pipe unix bash
3 Answers

You are sending a SIGINT to sed at the same time that you are sending it to ping. The sed is terminating before it sees ping's final message.

A simple workaround would be to use a version of sed that can ignore SIGINT. eg:

perl -p -e 'BEGIN{$SIG{INT}="IGNORE";} s/^/['"$1]: /"

As to the excellent questions raised by @EdMorton, I would just say that signal handling in the shell (and in Unix generally) is fickle. The behavior will greatly depend on the ordering of events.

user_1407500

Looks like in addition to @WilliamPursell's point that you could be interrupting your sed process at the same time as you're interrupting your ping process, you also need to group your commands when putting them in the background:

$ cat tst.sh
#!/usr/bin/env bash

log() {
    sed 's/^/[log]: /'
}

if [[ $1 == 1 ]]; then
    { ping 1.1.1.1 2>&1 | sed 's/^/[log]: /'; } &
else
    { ping 1.1.1.1 2>&1 | log; } &
fi

wait


$ ./tst.sh 1
[log]:
[log]: Pinging 1.1.1.1 with 32 bytes of data:
[log]: Reply from 1.1.1.1: bytes=32 time=21ms TTL=55
[log]:
[log]: Ping statistics for 1.1.1.1:
[log]:     Packets: Sent = 1, Received = 1, Lost = 0 (0% loss),
[log]: Approximate round trip times in milli-seconds:
[log]:     Minimum = 21ms, Maximum = 21ms, Average = 21ms
[log]: Control-C


$ ./tst.sh 2
[log]:
[log]: Pinging 1.1.1.1 with 32 bytes of data:
[log]: Reply from 1.1.1.1: bytes=32 time=29ms TTL=55
[log]:
[log]: Ping statistics for 1.1.1.1:
[log]:     Packets: Sent = 1, Received = 1, Lost = 0 (0% loss),
[log]: Approximate round trip times in milli-seconds:
[log]:     Minimum = 29ms, Maximum = 29ms, Average = 29ms
[log]: Control-C

Why that's necessary and why that difference shows up when piping to a function but not when piping directly to sed - I could guess but I'd rather someone who knows fills us in on that.

user_17450010

Force GNU Parallel to ignore SIGINT, so it will receive the input from the dying pings:

$ parallel -o --lb --tag ping {='$SIG{INT}=sub {}'=} ::: 1.1.1.1 8.8.8.8 9.9.9.9

1.1.1.1 PING 1.1.1.1 (1.1.1.1) 56(84) bytes of data.
1.1.1.1 64 bytes from 1.1.1.1: icmp_seq=1 ttl=57 time=11.6 ms
8.8.8.8 PING 8.8.8.8 (8.8.8.8) 56(84) bytes of data.
8.8.8.8 64 bytes from 8.8.8.8: icmp_seq=1 ttl=117 time=19.0 ms
9.9.9.9 PING 9.9.9.9 (9.9.9.9) 56(84) bytes of data.
9.9.9.9 64 bytes from 9.9.9.9: icmp_seq=1 ttl=57 time=18.2 ms
9.9.9.9 64 bytes from 9.9.9.9: icmp_seq=2 ttl=57 time=38.4 ms
1.1.1.1 64 bytes from 1.1.1.1: icmp_seq=2 ttl=57 time=38.1 ms
8.8.8.8 64 bytes from 8.8.8.8: icmp_seq=2 ttl=117 time=43.3 ms
9.9.9.9 64 bytes from 9.9.9.9: icmp_seq=3 ttl=57 time=18.5 ms
1.1.1.1 64 bytes from 1.1.1.1: icmp_seq=3 ttl=57 time=12.2 ms
8.8.8.8 64 bytes from 8.8.8.8: icmp_seq=3 ttl=117 time=19.2 ms
9.9.9.9 64 bytes from 9.9.9.9: icmp_seq=4 ttl=57 time=36.6 ms
1.1.1.1 64 bytes from 1.1.1.1: icmp_seq=4 ttl=57 time=3.19 ms
8.8.8.8 64 bytes from 8.8.8.8: icmp_seq=4 ttl=117 time=19.1 ms
^C
9.9.9.9
9.9.9.9 --- 9.9.9.9 ping statistics ---
9.9.9.9 5 packets transmitted, 4 received, 20% packet loss, time 4005ms
9.9.9.9 rtt min/avg/max/mdev = 18.166/27.903/38.404/9.611 ms
1.1.1.1 64 bytes from 1.1.1.1: icmp_seq=5 ttl=57 time=10.1 ms
1.1.1.1
1.1.1.1 --- 1.1.1.1 ping statistics ---
1.1.1.1 5 packets transmitted, 5 received, 0% packet loss, time 4004ms
1.1.1.1 rtt min/avg/max/mdev = 3.189/15.042/38.147/11.991 ms
8.8.8.8
8.8.8.8 --- 8.8.8.8 ping statistics ---
8.8.8.8 5 packets transmitted, 4 received, 20% packet loss, time 4003ms
8.8.8.8 rtt min/avg/max/mdev = 18.992/25.157/43.299/10.474 ms

Or:

$ parallel -o --lb --tagstring '[{}_log]:' ping {='$SIG{INT}=sub {}'=} ::: 1.1.1.1 8.8.8.8 9.9.9.9

-o was introduced in version 20220522.

user_3630280
Related