really add an explicit caller_ID string to cmd_wrapper

[moeller0]

https://github.com/lynxthecat/cake-autorate/blob/c80809586792291e9c5b49791a89804ae415d868/cake-autorate.sh#L637 Will this not result in fingering kill_and_wait_by_pid which does not give information about which pid we tried to kill... by all means keep the elegant $(caller) but also add a possibility to set a specific string...

Also I know naming is subjective, but debug_cmd() seems even worse than cmd_wrapper() as logging errors is only partially for debugging (normal users will not try to actually solve reported issues, but at best open an issue, the actual debugging happens later).

[moeller0]

Ah, I see caller is way more powerful, so this seems to solve part of my question, Still having a string to pass in is still useful, as it helps settling the question what the intent was....

[lynxthecat]

I gave some thought to renaming debug_cmd() but I quite like the name. Isn't the idea that we are trying to debug commands by prefixing debug_cmd prior to commands to help work out what's going on?

Regarding passing message, we know the exact point in the bash code that issued the error messages because we see the line that generated it and the entire function call history right back to main. With all that information I am wondering what benefit adding in a message gives? Could you give an example? The reason I am wondering is because I really like being able to keep it super simple:

debug_cmd cmd arguments

We'd need something like debug_cmd message cmd arguments, which is a little more cumbersome and unless there is a good reason to add in custom messages then I'm wondering if that's worth it.

[moeller0]

Isn't the idea that we are trying to debug commands by prefixing debug_cmd prior to commands to help work out what's going on?

Only partly, my idea would be to wrap all relevant commands to get actionable ERROR reports. Yes these help in debugging, but for most users these will help to figure out when to report a new issue. In general direction stderr to /dev/null is a dicy idea that assumes everything works perfectly all of time, which in my experience it does not ;) But for naming I happily accept your choices.

I gave some thought to renaming debug_cmd() but I quite like the name. Isn't the idea that we are trying to debug commands by prefixing debug_cmd prior to commands to help work out what's going on?

Regarding passing message, we know the exact point in the bash code that issued the error messages because we see the line that generated it and the entire function call history right back to main. With all that information I am wondering what benefit adding in a message gives? Could you give an example? The reason I am wondering is because I really like being able to keep it super simple:

debug_cmd cmd arguments

We'd need something like debug_cmd message cmd arguments, which is a little more cumbersome and unless there is a good reason to add in custom messages then I'm wondering if that's worth it.

But which version was the reporter running? Did he/she add/remove lines?

Could you give an example?

As I said, unless we know the exact state of cake-autorate.sh the line number itself is not as helpful as I would like this message to be...

[moeller0]

BTW, getting the whole call chain is clever, but I think this still wants at least an optional "intent string"...

[lynxthecat]

So take this output:

DEBUG; 2022-12-30-15:20:59; 1672413659.742161; Killing fping instance.
./cake-autorate.sh: line 628: /proc/1400/cmdline: No such file or directory
DEBUG; 2022-12-30-15:20:59; 1672413659.746755; pinger_pids[0] cmdline: /bin/bash./cake-autorate.sh
DEBUG; 2022-12-30-15:20:59; 1672413659.751015; debug_cmd: kill: invocation error silenced by request
DEBUG; 2022-12-30-15:20:59; 1672413659.757902; debug_cmd: 643 ./cake-autorate.sh: FAILURE (1): kill 1400
DEBUG; 2022-12-30-15:20:59; 1672413659.759276; debug_cmd: 643 ./cake-autorate.sh: LAST ERROR (./cake-autorate.sh: line 1094: kill: (1400) - No such process)
DEBUG; 2022-12-30-15:20:59; 1672413659.762970; debug_cmd: 643 ./cake-autorate.sh: CALL CHAIN: 665 kill_pinger ./cake-autorate.sh
DEBUG; 2022-12-30-15:20:59; 1672413659.766319; debug_cmd: 643 ./cake-autorate.sh: CALL CHAIN: 684 kill_pingers ./cake-autorate.sh
DEBUG; 2022-12-30-15:20:59; 1672413659.769738; debug_cmd: 643 ./cake-autorate.sh: CALL CHAIN: 887 maintain_pingers ./cake-autorate.sh
DEBUG; 2022-12-30-15:20:59; 1672413659.773187; debug_cmd: 643 ./cake-autorate.sh: CALL CHAIN: 1326 main ./cake-autorate.sh

What would we set the 'intent string' to? Maybe 'verify ping kill'?

[lynxthecat]

OK I see why we should add this now:

DEBUG; 2022-12-30-15:45:25; 1672415125.165572; monitor_achieved_rates_pid=1794 cmdline: /bin/bash./cake-autorate.sh
DEBUG; 2022-12-30-15:45:25; 1672415125.172457; debug_cmd: 637 ./cake-autorate.sh: SUCCESS: kill 1794
DEBUG; 2022-12-30-15:45:25; 1672415125.173909; Terminating maintain_log_file_pid: 1785.
DEBUG; 2022-12-30-15:45:25; 1672415125.175499; maintain_log_file_pid=1785 cmdline: /bin/bash./cake-autorate.sh
DEBUG; 2022-12-30-15:45:25; 1672415125.177256; maintain_log_file_pid=1785 cmdline: /bin/bash./cake-autorate.sh
DEBUG; 2022-12-30-15:45:25; 1672415125.184197; debug_cmd: 637 ./cake-autorate.sh: SUCCESS: kill 1785

[moeller0]

BTW, getting the whole call chain is clever, but I think this still wants at least an optional "intent string"...

To keep things simple I would try a single continuous string, like "pinger_pid" and then later "monitor_pid" so that we can figure out which of the two was causing the message.... This is mostly relevant in cases like kill_pinger() in which we do the same thing twice.... So something like:

DEBUG; 2022-12-30-15:45:25; 1672415125.172457; debug_cmd: pinger_pid: 637 ./cake-autorate.sh: SUCCESS: kill 1794

would allow to solve the ambiguity, no?

[lynxthecat]

How about if for each argument we split it out like:

arg1=4234 arg2=354234

[moeller0]

How about if for each argument we split it out like:

Not sure what you propose here... I am just looking for a way of pre-annotating debug_cmd output ;). While I am a big fan of explicit function arguments, I already compromised (in sqm-scripts) on passing the err_silence equivalent as environment variable (on the grounds that this usage will be rare and the normal usage does not need to be bothered with passing an empty argument like "". Something like:

err_silence=0 intent_string="kill pingers with a vengeance" debug_cmd kill "pingers_pid[$pinger]"

which in cases where annotation does not matter and silencing is not desired would shorten to"

debug_cmd kill "pingers_pid[$pinger]"

Personally I like the force a positional argument approach better, but not my call to make.

[lynxthecat]

What I mean is that rather than outputting the command in form:

kill 2421

We'd output in form kill pinger_pid[0]=53245

Which in this case would take out the reason for needing the debug reason line.

DEBUG; 2022-12-30-15:45:25; 1672415125.172457; debug_cmd: 637 ./cake-autorate.sh: SUCCESS: kill pingers_pid[0]=325325

[moeller0]

This would not help if a an argument is passed in directly instead of via a variable... really it is up to you, IMHO being able to pass a string is the most versatile approach here.

[lynxthecat]

OK yes you are right. Switching to this now.

[lynxthecat]

Fixed now. See this commit here: https://github.com/lynxthecat/cake-autorate/commit/c9c34bddecab88b077eda940fa749c9b811e5d4b.

Example output:

root@OpenWrt:~/cake-autorate# ./cake-autorate.sh
DEBUG; 2022-12-30-18:42:10; 1672425730.285597; Started maintain log file process with pid=5001
DEBUG; 2022-12-30-18:42:10; 1672425730.290647; Starting CAKE-autorate 1.2.0
DEBUG; 2022-12-30-18:42:10; 1672425730.291847; config_path: /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2022-12-30-18:42:10; 1672425730.293563; run_path: /var/run/cake-autorate/primary
DEBUG; 2022-12-30-18:42:10; 1672425730.295272; log_file_path: /var/log/cake-autorate.primary.log
DEBUG; 2022-12-30-18:42:10; 1672425730.297154; pinger_binary:fping
DEBUG; 2022-12-30-18:42:10; 1672425730.299000; Down interface: ifb-wan (5000 / 10000 / 80000)
DEBUG; 2022-12-30-18:42:10; 1672425730.300598; Up interface: wan (5000 / 10000 / 35000)
DEBUG; 2022-12-30-18:42:10; 1672425730.302315; rx_bytes_path: /sys/class/net/ifb-wan/statistics/tx_bytes
DEBUG; 2022-12-30-18:42:10; 1672425730.304190; tx_bytes_path: /sys/class/net/wan/statistics/tx_bytes
DEBUG; 2022-12-30-18:42:10; 1672425730.341277; Started monitor achieved rates process with pid=5010
DEBUG; 2022-12-30-18:42:10; 1672425730.375456; Started pinger 0 with pid=5013
DEBUG; 2022-12-30-18:42:10; 1672425730.378727; pinger_pids[0]=5013 cmdline: fping--timestamp--loop--period300--interval50--timeout100001.1.1.11.0.0.18.8.8.88.8.4.49.9.9.99.9.9.10
DEBUG; 2022-12-30-18:42:10; 1672425730.382909; monitor_pids[0]=5014 cmdline: /bin/bash./cake-autorate.sh
^CINFO; 2022-12-30-18:42:10; 1672425730.854444;
INFO; 2022-12-30-18:42:10; 1672425730.856248; Killing all background processes and cleaning up temporary files.
DEBUG; 2022-12-30-18:42:10; 1672425730.858153; Terminating maintain_pingers_pid: 5011.
DEBUG; 2022-12-30-18:42:10; 1672425730.860551; maintain_pingers_pid=5011 cmdline: /bin/bash./cake-autorate.sh
DEBUG; 2022-12-30-18:42:11; 1672425731.396071; Reflector maintenance terminated.
DEBUG; 2022-12-30-18:42:11; 1672425731.398682; Killing fping instance.
DEBUG; 2022-12-30-18:42:11; 1672425731.402222; expected pinger_pids[0] process: 5013 does not exist - nothing to kill.
DEBUG; 2022-12-30-18:42:11; 1672425731.405803; monitor_pids[0]=5014 cmdline: /bin/bash./cake-autorate.sh
DEBUG; 2022-12-30-18:42:11; 1672425731.414357; debug_cmd: err_silence=0; debug_msg=monitor_pids[0]; caller_id=638 ./cake-autorate.sh; command=kill 5014; result=SUCCESS
DEBUG; 2022-12-30-18:42:11; 1672425731.435650; Terminating monitor_achieved_rates_pid: 5010.
DEBUG; 2022-12-30-18:42:11; 1672425731.436946; monitor_achieved_rates_pid=5010 cmdline: /bin/bash./cake-autorate.sh
DEBUG; 2022-12-30-18:42:11; 1672425731.439120; monitor_achieved_rates_pid=5010 cmdline: /bin/bash./cake-autorate.sh
DEBUG; 2022-12-30-18:42:11; 1672425731.444915; debug_cmd: err_silence=0; debug_msg=monitor_achieved_rates_pid; caller_id=638 ./cake-autorate.sh; command=kill 5010; result=SUCCESS
DEBUG; 2022-12-30-18:42:11; 1672425731.446939; Terminating maintain_log_file_pid: 5001.
DEBUG; 2022-12-30-18:42:11; 1672425731.449040; maintain_log_file_pid=5001 cmdline: /bin/bash./cake-autorate.sh
DEBUG; 2022-12-30-18:42:11; 1672425731.451105; maintain_log_file_pid=5001 cmdline: /bin/bash./cake-autorate.sh
DEBUG; 2022-12-30-18:42:11; 1672425731.457325; debug_cmd: err_silence=0; debug_msg=maintain_log_file_pid; caller_id=638 ./cake-autorate.sh; command=kill 5001; result=SUCCESS

If you agree please can you mark this issue as closed?