Init.d PROCD script log file handling

Lynx · February 20, 2022, 8:28pm

With init.d file below (thanks @jow!) everything gets written out correctly to my chosen log file at /tmp/cake-autorate.log. Everything works fine when I issue service stop and then start. However if I issue service restart, then I get weird behaviour where the log entries seem to get prepended to lines like:

/root/CAKE-autorate/monitor_reflector_path.sh: line 30: echo: write error: Broken pipe

Do I need to reset the log file at some point? Not sure how to best manage this.

Any ideas?

#!/bin/sh /etc/rc.common

START=97
STOP=4
USE_PROCD=1

start_service() {
        procd_open_instance
        procd_set_param command /root/CAKE-autorate/CAKE-autorate.sh &> /tmp/cake-autorate.log
        # uncomment if you want procd to restart your script if it terminated for whatever reason
        #procd_set_param respawn
        procd_close_instance
}

anon89577378 · February 21, 2022, 9:14am

Does this commented line of code handle that scenario?

# uncomment if you want procd to restart your script if it terminated for whatever reason
#procd_set_param respawn

Lynx · February 21, 2022, 1:27pm

Thanks - good suggestion. Yes that may well be fine, and I also like the ability to redirect stdout and stderr to logger with the right parameters as explained on the wiki.

I'm just trying to figure out what is going on in terms of when I simply issue the restart switch, because I see the broken pipe line:

/root/CAKE-autorate/monitor_reflector_path.sh: line 30: echo: write error: Broken pipe

And then new values get prepended to the file before that broken pipe line. Seems very strange!

Lynx · February 21, 2022, 10:08pm

@jow could you advise: what is the correct way to redirect output to /tmp log file as in below?

#!/bin/sh /etc/rc.common
 
START=97
STOP=4
USE_PROCD=1
 
start_service() {
        procd_open_instance
        procd_set_param command /root/CAKE-autorate/CAKE-autorate.sh &> /tmp/cake-autorate.log
        # uncomment if you want procd to restart your script if it terminated for whatever reason
        #procd_set_param respawn   
        procd_close_instance
}

I tried:

procd_set_param command "/root/CAKE-autorate/CAKE-autorate.sh &> /tmp/cake-autorate.log"

But no dice.

jow · February 21, 2022, 10:10pm

The command param expects an argument vector, you probably need something like this:

procd_set_param command /bin/bash -c '/root/CAKE-autorate/CAKE-autorate.sh &> /tmp/cake-autorate.log'

Lynx · February 21, 2022, 10:55pm

Thanks I will try it!

Lynx · February 22, 2022, 7:39pm

So it worked in the sense that the log file got written to, but it did not work in the sense that now with the 'bash -c' invocation when procd tries to kill it, the kill doesn't get trapped as I would have expected. So all the child processes remain.

root@OpenWrt:~# ps |grep bash
 8214 root      1248 R    grep bash
root@OpenWrt:~# service cake-autorate start
root@OpenWrt:~# ps |grep bash
 8235 root      2304 S    /bin/bash -c /root/CAKE-autorate/CAKE-autorate.sh &> /tmp/cake-autorate.log
 8237 root      2472 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8249 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8250 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8252 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8253 root      2460 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8254 root      2444 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8365 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8367 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
13447 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
13452 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
13466 root      1248 S    grep bash
13475 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
13480 root      2464 R    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
root@OpenWrt:~# service cake-autorate stop
root@OpenWrt:~# ps |grep bash
 8237 root      2472 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8249 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8250 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8252 root      2464 R    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8253 root      2460 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
 8254 root      2444 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
16549 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
16552 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
19025 root      2464 S    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
19067 root      1248 S    grep bash
19074 root      2464 R    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
19075 root      2464 R    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh
19076 root      2464 R    {CAKE-autorate.s} /bin/bash /root/CAKE-autorate/CAKE-autorate.sh

Any idea what's going on here?

Here is the exit/trap I am relying upon to kill background processes:

#!/bin/bash

# CAKE-autorate automatically adjusts bandwidth for CAKE in dependence on detected load and OWD/RTT

# inspired by @moeller0 (OpenWrt forum)
# initial sh implementation by @Lynx (OpenWrt forum)
# requires packages: bash, iputils-ping, coreutils-date, coreutils-sleep, inotifywait

trap cleanup_and_killall INT TERM EXIT

cleanup_and_killall()
{
	echo "Killing all background processes and cleaning up /tmp files."
	trap - INT && trap - TERM && trap - EXIT && kill -- ${bg_PIDs[@]}
	[ -d "/tmp/CAKE-autorate" ] && rm -r "/tmp/CAKE-autorate"
	exit
}

moeller0 · February 22, 2022, 7:46pm

I really would handle log file writing from inside the script (controlled via settings in defaults.sh) explicitly instead of redirecting general output into a file...

Lynx · February 22, 2022, 7:50pm

Thanks. Is there an elegant way to make it such that when script invoked directly in foreground you see output, but when invoked from procd it writes to log file? Maybe I should just take argument that when set tells it to write to log file or stdout? And then in procd set parameter appropriately?

moeller0 · February 22, 2022, 8:22pm

Yeah, I think handling these separately makes a ton of sense. The log file should be written in a way that makes it easy to parse (like all lines have identical fields). The console output, likely is read by a human can easily interleave different "record types", like per reflector data, general state data, and eve errors and warnings (these ideally should also appear in the system log).

Lynx · February 22, 2022, 8:31pm

Cheers. For my own understanding do you or @jow know why having procd invoke the script via 'bash -c' prevents the procd stop order and resultant exit hitting the trap function inside the bash script?

moeller0 · February 23, 2022, 7:56am

Sorry, no idea.

jow · February 23, 2022, 7:58am

I suppose the signal is delivered to bash in that case and not your script, then not forwarded for whatever reason.

Lynx · February 23, 2022, 8:09am

Curiously invoking manually using 'bash -c' works fine:

root@OpenWrt:~/CAKE-autorate# bash -c ./CAKE-autorate.sh
rx_bytes_path: /sys/class/net/veth-lan/statistics/tx_bytes
tx_bytes_path: /sys/class/net/wan/statistics/tx_bytes
^CKilling all background processes and cleaning up /tmp files.

Any idea what signal would get sent? Term to bash and then would bash forward term to script?

jow · February 23, 2022, 8:11am

Likely related to the same session leader issue.

Anyhow, I do agree with @moeller0 that the logging business should happen inside the script. You could use a function like the one below:

log() {
    # test if stdout is a tty (terminal)
    if [ -t 1 ]; then
        echo "$@"
    else
        echo "$@" >> /tmp/cake-autorate.log
    fi
}

Then invoke log "Message" instead of echo "Message" whenever you want to output something.

Lynx · February 23, 2022, 8:12am

It couldn't be that something other than int term or exit gets passed along? Like sigterm?

Lynx · February 23, 2022, 9:00am

Sweet thanks! Perfect.

I am still curious about signal getting lost. Maybe it's sigterm not term or something?

moeller0 · February 23, 2022, 9:28am

Another idea, use tail -f to show the log file when runing by hand on a terinal?

Lynx · February 26, 2022, 8:56pm

@jow and @moeller0 or perhaps @vgaetera new technical question. How do I get the process id of:

tail -f file |

This starts background process but I don't know how to get the process id in this situation. $! can't be used because the tail -f keeps running.

Lynx · March 1, 2022, 1:35pm

Solved by ichernev[m] on the #openwrt IRC channel, as follows:

trap cleanup_and_killall EXIT INT TERM
 
export pid
cleanup_and_killall()
{
	echo "Killing $pid"
	trap - INT && trap - TERM && trap - EXIT
        kill -- $pid
	# [ -d "/tmp/CAKE-autorate" ] && rm -r "/tmp/CAKE-autorate"
	exit
}
 
 
# set -m
 
touch ping_out
ping_wrap() {
	exec ping "$@" 2>&1 >ping_out
}
 
pong_wrap() {
	(tail -f ping_out & echo $! >&3) 3> pid_file | while read line; do
		echo "BLA $line"
	done
}
 
ping_wrap 8.8.8.8 &
export pid="$! $pid"
ping_wrap 8.8.4.4 &
export pid="$! $pid"
 
pong_wrap &
sleep 1
export pid="`cat pid_file` $pid"
 
 
echo "Got $pid -- to be killed"
sleep 30
echo "now exiting"