search

lynxthecat / cake-autorate

Eliminate the excess latency and jitter terrorizing your 4G, 5G, LTE, Starlink or other variable rate connection!
https://www.bufferbloat.net
GNU General Public License v2.0
275 stars 24 forks source link

1.1.0: Always put time stamps at start of log line #46

Closed richb-hanover closed 2 years ago

richb-hanover commented 2 years ago

Feature Request: I'd like to see the time stamps at the front of the line, before the condition string. The strong left-alignment makes it easier for the eye to follow what's happening. Compare:

2022-09-28-15:45:45; 1664394345.479548; CAKE-CHANGE; tc qdisc change root dev wan cake bandwidth 76255Kbit
2022-09-28-15:45:45; 1664394345.530489; CAKE-CHANGE; tc qdisc change root dev wan cake bandwidth 76500Kbit
2022-09-28-15:45:55; 1664394355.895255; CAKE-CHANGE; tc qdisc change root dev wan cake bandwidth 75500Kbit
2022-09-28-15:47:18; 1664394438.474968; DEBUG; Connection idle. Enforcing minimum shaper rates and waiting for minimum load.
2022-09-28-15:47:18; 1664394438.476589; CAKE-CHANGE; tc qdisc change root dev ifb4wan cake bandwidth 70000Kbit
2022-09-28-15:47:18; 1664394438.481823; CAKE-CHANGE; tc qdisc change root dev wan cake bandwidth 70000Kbit
2022-09-28-16:12:11; 1664395931.501696; DEBUG; concurrent_read_positive_integer() misfire with the following particulars:
2022-09-28-16:12:11; 1664395931.502655; DEBUG; caller=231 ./cake-autorate.sh; value=; and path=/tmp/cake-autorate/dl_achieved_rate_kbps

versus:

CAKE-CHANGE; 2022-09-28-15:45:45; 1664394345.479548; tc qdisc change root dev wan cake bandwidth 76255Kbit
CAKE-CHANGE; 2022-09-28-15:45:45; 1664394345.530489; tc qdisc change root dev wan cake bandwidth 76500Kbit
CAKE-CHANGE; 2022-09-28-15:45:55; 1664394355.895255; tc qdisc change root dev wan cake bandwidth 75500Kbit
DEBUG; 2022-09-28-15:47:18; 1664394438.474968; Connection idle. Enforcing minimum shaper rates and waiting for minimum load.
CAKE-CHANGE; 2022-09-28-15:47:18; 1664394438.476589; tc qdisc change root dev ifb4wan cake bandwidth 70000Kbit
CAKE-CHANGE; 2022-09-28-15:47:18; 1664394438.481823; tc qdisc change root dev wan cake bandwidth 70000Kbit
DEBUG; 2022-09-28-16:12:11; 1664395931.501696; concurrent_read_positive_integer() misfire with the following particulars:
DEBUG; 2022-09-28-16:12:11; 1664395931.502655; caller=231 ./cake-autorate.sh; value=; and path=/tmp/cake-autorate/dl_achieved_rate_kbps

Thanks.

lynxthecat commented 2 years ago

I'd be fine with this. But I can see arguments both ways . Any thoughts @patrakov and @moeller0?

moeller0 commented 2 years ago

No, I want the record type at the very beginning of the line, this allows a line-by-line parser to only look at the first four characters (requiring no dissection into individual fields). (Yes with a guaranteed length for the first two fields this approach could also pick the record type from an offset, but that puts in additional assumptions)

BUT, I am fine with making that field fixed length so the alignment stays intact. @richb-hanover would that be a workable compromise? Fixed length could be achieved by padding short entries or by requiring a fixed length for the record type Or we could simply generate three log files: for DATA, CAKE-CHANGE, and DEBUG individually, at which point the rule could be: first line contains the header all other lines contain data. (the console log could still keep all of these interleaved).

richb-hanover commented 2 years ago

I would prefer to prioritize a decrease in cognitive load (putting the time stamps at the beginning) over a minor increase in code. That said, I definitely support fixed-length time stamp fields.

I have a PR in progress that moves the time stamps and also logs all variables at what seem to be interesting points - when the CAKE parameters get adjusted. I want to review the data I've collected so far to see what it's telling me. Thanks.

lynxthecat commented 2 years ago

I see where you are coming from @richb-hanover. I used to pad all the data elements to make it pleasing to the eye when viewing the rolling output lines, but it has got too difficult because if I pad to make it work in all situations the width exceeds the width of my laptop screen (and perhaps even now my desktop screen with the OWD columns). I tried tabs at one point but that didn't quite work either.

So I gave up on padding and have come to terms with it:

image

And of course whenever it is exported to Excel it looks nice anyway:

image

Example.xlsx

.. so I'm inclined to think we're OK on this front?

lynxthecat commented 2 years ago

... btw @richb-hanover one thing I love about the code now with autologging is that when running as a service any time you want to see what's going on under the hood with cake-autorate you just need to run:

tail -f /tmp/cake-autorate.log

and this presents a window into the cake-autorate dimension so you can get a view of what's happening:

image

... and then if I download some data:

image

Terrible congestion right now at 20:20 UK time. Can't breach 10 Mbit/s without bufferbloat. Then as the evening wears on into the night it will go back up well above 30 Mbit/s until it hits bufferbloat.

richb-hanover commented 2 years ago

Yes, having log files to show what's up is helpful.

Terrible congestion right now at 20:20 UK time. Can't breach 10 Mbit/s without bufferbloat. Then as the evening wears on into the night it will go back up well above 30 Mbit/s until it hits bufferbloat.

And another good thing - having the technology to do something about it. Better living through Science!

moeller0 commented 2 years ago

@Lynx, maybe we can really either use a fixed length with padding for the record type or always use, say 8 characters? I think that ideally the log files will be parsed and presented by code (so alignment does not matter much) but for quick debugging it seems quite user-friendly to make at least the timestamps easy to compare/read?

Then again, the lines are essentially ordered by write time to the sequence alone is informative.

I am more hesitant to go for record type at later position as we already twiddled with the length of the timestamp fields in the past and might do so again. So the first field is somewhat special, so let's put it to good use

lynxthecat commented 2 years ago

If fixed length what would we use?

We have at the moment:

ERROR # ERROR
DEBUG # DEBUG
DATA # DATA
CAKE-CHANGE # SHAPER RATE CHANGE
INFO # INFO

We could use:

ERR # ERROR
DBG # DEBUG
DAT # DATA
SRC # SHAPER RATE CHANGE
INF # INFO

Or:

ERRO # ERROR
DEBG # DEBUG
DATA # DATA
SHRC # SHAPER RATE CHANGE
INFO # INFO

Or something else?

moeller0 commented 2 years ago

How about:

ERROR_
DEBUG_
DATA__
SHAPER
INFO__

I like full words better which requires manual padding... or simply use a fixed width for that single field by padding in printf? I took the liberty to rename CAKE-CHANGE since this is quite long.

lynxthecat commented 2 years ago

OK @richb-hanover how about the above but with spaces to pad to fixed width?

richb-hanover commented 2 years ago

I have a vague unsettled feeling about doing this. I am very used to log files with time stamps at the left. ("TRADITION!" as he breaks into the "Fiddler on the Roof" song :-)

But, this is hardly a critical feature. As for spaces or trailing "_" - could you copy/paste some representative lines, insert the proposed fields, so we can compare their look here? Thanks.

moeller0 commented 2 years ago

I have a vague unsettled feeling about doing this. I am very used to log files with time stamps at the left. ("TRADITION!" as he breaks into the "Fiddler on the Roof" song :-)

I understand where you appear to be coming from. I am not looking at this from the "how does it look to me as consumer" but from the "what the most robust and reliable" way to make this easy to parse (as for plotting some program will need to read in the data). And short of a singular record type an unambiguous and cheap to detect record type filed is quite helpful (being a biologist I have form in designing bad intermediate data formats and having to make up for this in writing complicated and fickle parsers after the fact, I just offer what I have earned over the years, which essentially boils down to keep it simple and try to write aimed at a parser not a human*)

*) json takes this idea to an extreme IMHO, I am fine with a 2D table of as in our case multiple interleaved 2D tables, but there needs to be an easy and cheap way to de-interleave the records again...

richb-hanover commented 2 years ago

I am conceding the point. I just want to know which fixed-length type field might look better to my eye (our eyes): "DATA " (with two trailing spaces) or "DATA__" (two trailing underscores).

I would just like to see a comparison of the two alternatives applied to some representative log lines. Thanks.

moeller0 commented 2 years ago 
SHAPER; 2022-09-28-15:45:45; 1664394345.479548; tc qdisc change root dev wan cake bandwidth 76255Kbit
SHAPER; 2022-09-28-15:45:45; 1664394345.530489; tc qdisc change root dev wan cake bandwidth 76500Kbit
SHAPER; 2022-09-28-15:45:55; 1664394355.895255; tc qdisc change root dev wan cake bandwidth 75500Kbit
DEBUG_; 2022-09-28-15:47:18; 1664394438.474968; Connection idle. Enforcing minimum shaper rates and waiting for minimum load.
SHAPER; 2022-09-28-15:47:18; 1664394438.476589; tc qdisc change root dev ifb4wan cake bandwidth 70000Kbit
SHAPER; 2022-09-28-15:47:18; 1664394438.481823; tc qdisc change root dev wan cake bandwidth 70000Kbit
DEBUG_; 2022-09-28-16:12:11; 1664395931.501696; concurrent_read_positive_integer() misfire with the following particulars:
DATA__; 2022-09-28-16:12:11; 1664395931.502655; caller=231 ./cake-autorate.sh; value=; and path=/tmp/cake-autorate/dl_achieved_rate_kbps

OR

SHAPER; 2022-09-28-15:45:45; 1664394345.479548; tc qdisc change root dev wan cake bandwidth 76255Kbit
SHAPER; 2022-09-28-15:45:45; 1664394345.530489; tc qdisc change root dev wan cake bandwidth 76500Kbit
SHAPER; 2022-09-28-15:45:55; 1664394355.895255; tc qdisc change root dev wan cake bandwidth 75500Kbit
DEBUG ; 2022-09-28-15:47:18; 1664394438.474968; Connection idle. Enforcing minimum shaper rates and waiting for minimum load.
SHAPER; 2022-09-28-15:47:18; 1664394438.476589; tc qdisc change root dev ifb4wan cake bandwidth 70000Kbit
SHAPER; 2022-09-28-15:47:18; 1664394438.481823; tc qdisc change root dev wan cake bandwidth 70000Kbit
DEBUG ; 2022-09-28-16:12:11; 1664395931.501696; concurrent_read_positive_integer() misfire with the following particulars:
DATA  ; 2022-09-28-16:12:11; 1664395931.502655; caller=231 ./cake-autorate.sh; value=; and path=/tmp/cake-autorate/dl_achieved_rate_kbps

Short of real data I just changed the last type label to DATA but the entry is a DEBUG record type, I hope this still illustrates the issue well enough.

richb-hanover commented 2 years ago

Thanks for doing that. I copy/pasted multiple copies of each of those sets. I don't really have a preference (" " or "_"). The "; " that delimits fields forces a strong alignment and separation that prevents the differences from being distracting.

So, I think we're nailing down the log format:

I don't think it's necessary for log_msg() to enforce the six-character padding. We create few enough log lines, and an aberrant length will be extremely obvious during debugging.

lynxthecat commented 2 years ago

How about:

# Send message to fifo for sending to log file w/ log file rotation check
log_msg()
{
        local type=$1
        local msg=$2

        (($log_to_file)) && printf '%6s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg" > /tmp/cake-autorate/log_fifo
        [[ -t 1 ]] && printf '%6s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg"
}

# Send message directly to log file wo/ log file rotation check (e.g. before maintain_log_file() is up)
log_msg_bypass_fifo()
{

        local type=$1
        local msg=$2

        (($log_to_file)) && printf '%6s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg" >> /tmp/cake-autorate.log
        [[ -t 1 ]] && printf '%6s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg"

}
root@OpenWrt:~/cake-autorate# ./cake-autorate.sh
 DEBUG; 2022-09-30-17:23:31; 1664555011.680977; Starting CAKE-autorate 1.1.0
 DEBUG; 2022-09-30-17:23:31; 1664555011.683357; Down interface: ifb-dl (10000 / 25000 / 80000)
 DEBUG; 2022-09-30-17:23:31; 1664555011.685287; Up interface: ifb-ul (25000 / 30000 / 35000)
 DEBUG; 2022-09-30-17:23:31; 1664555011.687433; rx_bytes_path: /sys/class/net/ifb-dl/statistics/tx_bytes
 DEBUG; 2022-09-30-17:23:31; 1664555011.689211; tx_bytes_path: /sys/class/net/ifb-ul/statistics/rx_bytes
SHAPER; 2022-09-30-17:23:31; 1664555011.719177; tc qdisc change root dev ifb-dl cake bandwidth 25000Kbit
SHAPER; 2022-09-30-17:23:31; 1664555011.729058; tc qdisc change root dev ifb-ul cake bandwidth 30000Kbit
HEADER; LOG_DATETIME; LOG_TIMESTAMP; PROC_TIME_US; DL_ACHIEVED_RATE_KBPS; UL_ACHIEVED_RATE_KBPS; DL_LOAD_PERCENT; UL_LOAD_PERCENT; RTT_TIMESTAMP; REFLECTOR; SEQUENCE; DL_OWD_BASELINE; DL_OWD_US; DL_OWD_DELTA_US; UL_OWD_BASELINE; UL_OWD_US; UL_OWD_DELTA_US; ADJ_DELAY_THR; SUM_DL_DELAYS; SUM_UL_DELAYS; DL_LOAD_CONDITION; UL_LOAD_CONDITION; CAKE_DL_RATE_KBPS; CAKE_UL_RATE_KBPS
  DATA; 2022-09-30-17:23:31; 1664555011.908925; 1664555011.907687; 286; 10; 1; 0; 1664555011.898460; 1.1.1.1; 0; 96800; 52000; -448000; 96800; 52000; -448000; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
  DATA; 2022-09-30-17:23:31; 1664555011.971272; 1664555011.969641; 286; 10; 1; 0; 1664555011.952440; 1.0.0.1; 0; 98600; 54000; -446000; 98600; 54000; -446000; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
  DATA; 2022-09-30-17:23:31; 1664555011.989972; 1664555011.988359; 22607; 1354; 90; 4; 1664555011.974960; 8.8.8.8; 0; 86090; 40100; -459900; 86090; 40100; -459900; 12966; 0; 0; dl_high; ul_low; 25000; 30000
  DATA; 2022-09-30-17:23:32; 1664555012.014592; 1664555012.012628; 22607; 1354; 90; 4; 1664555012.000850; 8.8.4.4; 0; 75200; 28000; -472000; 75200; 28000; -472000; 12966; 0; 0; dl_high; ul_low; 25000; 30000
SHAPER; 2022-09-30-17:23:32; 1664555012.135090; tc qdisc change root dev ifb-dl cake bandwidth 25250Kbit
  DATA; 2022-09-30-17:23:32; 1664555012.149189; 1664555012.146493; 22607; 1354; 90; 4; 1664555012.106080; 1.1.1.1; 1; 59630; 55500; -41300; 59630; 55500; -41300; 12964; 0; 0; dl_high; ul_low; 25250; 30000
SHAPER; 2022-09-30-17:23:32; 1664555012.163702; tc qdisc change root dev ifb-dl cake bandwidth 25502Kbit
  DATA; 2022-09-30-17:23:32; 1664555012.181475; 1664555012.178968; 22607; 1354; 89; 4; 1664555012.151360; 1.0.0.1; 1; 57560; 53000; -45600; 57560; 53000; -45600; 12961; 0; 0; dl_high; ul_low; 25502; 30000
SHAPER; 2022-09-30-17:23:32; 1664555012.193241; tc qdisc change root dev ifb-dl cake bandwidth 25757Kbit
  DATA; 2022-09-30-17:23:32; 1664555012.208437; 1664555012.207004; 22328; 1332; 87; 4; 1664555012.168600; 8.8.8.8; 1; 41594; 36650; -49440; 41594; 36650; -49440; 12959; 0; 0; dl_high; ul_low; 25757; 30000
moeller0 commented 2 years ago

This makes parsing harder than necessary, if all is left aligned it is probably enough to read the first 3-4 characters with left space padding matching pattern will change if a longer entry is added, say SHAPERS ;)

moeller0 commented 2 years ago

Mind you safest currently is matching all six characters, but the problems stays if we want to extend to more than 6 chars parsers will need to be rewritten.

lynxthecat commented 2 years ago 
# Send message to fifo for sending to log file w/ log file rotation check
log_msg()
{
        local type=$1
        local msg=$2

        (($log_to_file)) && printf '%-6s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg" > /tmp/cake-autorate/log_fifo
        [[ -t 1 ]] && printf '%-6s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg"
}

# Send message directly to log file wo/ log file rotation check (e.g. before maintain_log_file() is up)
log_msg_bypass_fifo()
{

        local type=$1
        local msg=$2

        (($log_to_file)) && printf '%-6s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg" >> /tmp/cake-autorate.log
        [[ -t 1 ]] && printf '%-6s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg"

}
root@OpenWrt:~/cake-autorate# ./cake-autorate.sh
DEBUG ; 2022-09-30-17:45:03; 1664556303.669988; Starting CAKE-autorate 1.1.0
DEBUG ; 2022-09-30-17:45:03; 1664556303.672638; Down interface: ifb-dl (10000 / 25000 / 80000)
DEBUG ; 2022-09-30-17:45:03; 1664556303.675694; Up interface: ifb-ul (25000 / 30000 / 35000)
DEBUG ; 2022-09-30-17:45:03; 1664556303.678337; rx_bytes_path: /sys/class/net/ifb-dl/statistics/tx_bytes
DEBUG ; 2022-09-30-17:45:03; 1664556303.680927; tx_bytes_path: /sys/class/net/ifb-ul/statistics/rx_bytes
SHAPER; 2022-09-30-17:45:03; 1664556303.710515; tc qdisc change root dev ifb-dl cake bandwidth 25000Kbit
SHAPER; 2022-09-30-17:45:03; 1664556303.720208; tc qdisc change root dev ifb-ul cake bandwidth 30000Kbit
HEADER; LOG_DATETIME; LOG_TIMESTAMP; PROC_TIME_US; DL_ACHIEVED_RATE_KBPS; UL_ACHIEVED_RATE_KBPS; DL_LOAD_PERCENT; UL_LOAD_PERCENT; RTT_TIMESTAMP; REFLECTOR; SEQUENCE; DL_OWD_BASELINE; DL_OWD_US; DL_OWD_DELTA_US; UL_OWD_BASELINE; UL_OWD_US; UL_OWD_DELTA_US; ADJ_DELAY_THR; SUM_DL_DELAYS; SUM_UL_DELAYS; DL_LOAD_CONDITION; UL_LOAD_CONDITION; CAKE_DL_RATE_KBPS; CAKE_UL_RATE_KBPS
DATA  ; 2022-09-30-17:45:03; 1664556303.897237; 1664556303.895981; 114; 7; 0; 0; 1664556303.887840; 1.1.1.1; 0; 90410; 44900; -455100; 90410; 44900; -455100; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
DATA  ; 2022-09-30-17:45:03; 1664556303.964570; 1664556303.957008; 114; 7; 0; 0; 1664556303.937460; 1.0.0.1; 0; 90095; 44550; -455450; 90095; 44550; -455450; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
DATA  ; 2022-09-30-17:45:03; 1664556303.982455; 1664556303.980752; 22244; 4112; 88; 13; 1664556303.965710; 8.8.8.8; 0; 79970; 33300; -466700; 79970; 33300; -466700; 12966; 0; 0; dl_high; ul_low; 25000; 30000
DATA  ; 2022-09-30-17:45:04; 1664556304.024764; 1664556304.023651; 22244; 4112; 88; 13; 1664556304.008140; 8.8.4.4; 0; 76460; 29400; -470600; 76460; 29400; -470600; 12966; 0; 0; dl_high; ul_low; 25000; 30000
SHAPER; 2022-09-30-17:45:04; 1664556304.124665; tc qdisc change root dev ifb-dl cake bandwidth 25250Kbit
DATA  ; 2022-09-30-17:45:04; 1664556304.133152; 1664556304.131844; 22244; 4112; 88; 13; 1664556304.104770; 1.1.1.1; 1; 56291; 52500; -37910; 56291; 52500; -37910; 12964; 0; 0; dl_high; ul_low; 25250; 30000
SHAPER; 2022-09-30-17:45:04; 1664556304.154794; tc qdisc change root dev ifb-dl cake bandwidth 25502Kbit
DATA  ; 2022-09-30-17:45:04; 1664556304.177568; 1664556304.174549; 22244; 4112; 88; 13; 1664556304.142120; 1.0.0.1; 1; 50679; 46300; -43795; 50679; 46300; -43795; 12961; 0; 0; dl_high; ul_low; 25502; 30000
SHAPER; 2022-09-30-17:45:04; 1664556304.191795; tc qdisc change root dev ifb-dl cake bandwidth 25757Kbit
DATA  ; 2022-09-30-17:45:04; 1664556304.208732; 1664556304.206694; 22174; 3330; 86; 11; 1664556304.169980; 8.8.8.8; 1; 39497; 35000; -44970; 39497; 35000; -44970; 12959; 0; 0; dl_high; ul_low; 25757; 30000
SHAPER; 2022-09-30-17:45:04; 1664556304.238560; tc qdisc change root dev ifb-dl cake bandwidth 26014Kbit
DATA  ; 2022-09-30-17:45:04; 1664556304.248385; 1664556304.247115; 22174; 3330; 86; 11; 1664556304.224160; 8.8.4.4; 1; 40991; 37050; -39410; 40991; 37050; -39410; 12956; 0; 0; dl_high; ul_low; 26014; 30000
SHAPER; 2022-09-30-17:45:04; 1664556304.309466; tc qdisc change root dev ifb-dl cake bandwidth 26274Kbit
DATA  ; 2022-09-30-17:45:04; 1664556304.323504; 1664556304.321919; 22174; 3330; 85; 11; 1664556304.296410; 1.1.1.1; 2; 48919; 48100; -8191; 48919; 48100; -8191; 12954; 0; 0; dl_high; ul_low; 26274; 30000
^CINFO  ; 2022-09-30-17:45:04; 1664556304.369408;
INFO  ; 2022-09-30-17:45:04; 1664556304.371498; Killing all background processes and cleaning up /tmp files.

Wouldn't it look nicer to have padding after the ; or would that also break stuff? I find the spaces before the ; a little ugly. Then again I don't know how I'd manage that with printf.

@moeller0 and @richb-hanover we can also consider giving a different output for console vs log file? As in we could keep the original logging code for the log file and say just zero-pad and remove semicolons for console? Thoughts on this?

This would be easy since I already separate out the logging printf lines for console vs log file.

moeller0 commented 2 years ago

Wouldn't it look nicer to have padding after the ; or would that also break stuff? I find the spaces before the ; a little ugly. Then again I don't know how I'd manage that with printf.

That gets ugly quickly. The problem is that "CSV" or here better "SSV" is inherently an unpleasant format if not all fields are guaranteed to have entries of equal length (which gets even nastier with proportional fonts). Using "; " as separator as you do helps a bit, but this really is a format intended for being read by a machine...

@moeller0 and @richb-hanover we can also consider giving a different output for console vs log file? As in we could keep the original logging code for the log file and say just zero-pad and remove semicolons for console? Thoughts on this?

This is fine, all my parsing comments really are targeted at a log file, the console output can look different. But I think @richb-hanover is also intending to "mine" the log files so not sure whether that helps?

lynxthecat commented 2 years ago

What do you think @richb-hanover? Keep log file as was but beautify console output to left or right space pad first column and remove semicolons?

I will certainly change CAKE-CHANGE to SHAPER.

@richb-hanover how about this:

# Send message to fifo for sending to log file w/ log file rotation check
log_msg()
{
        local type=$1
        local msg=$2

        (($log_to_file)) && printf '%s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg" > /tmp/cake-autorate/log_fifo
        [[ -t 1 ]] && printf '%6s %(%F-%H:%M:%S)T %s %s\n' "$type" -1 "$EPOCHREALTIME" "${msg//;}"
}

# Send message directly to log file wo/ log file rotation check (e.g. before maintain_log_file() is up)
log_msg_bypass_fifo()
{

        local type=$1
        local msg=$2

        (($log_to_file)) && printf '%s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg" >> /tmp/cake-autorate.log
        [[ -t 1 ]] && printf '%6s %(%F-%H:%M:%S)T %s %s\n' "$type" -1 "$EPOCHREALTIME" "${msg//;}"

}

print_header()
{
        header="HEADER; LOG_DATETIME; LOG_TIMESTAMP; PROC_TIME_US; DL_ACHIEVED_RATE_KBPS; UL_ACHIEVED_RATE_KBPS; DL_LOAD_PERCENT; UL_LOAD_PERCENT; RTT_TIMESTAMP; REFLECTOR; SEQUENCE; DL_OWD_BASELINE; DL_OWD_US; DL_OWD_DELTA_US; UL_OWD_BASELINE; UL_OWD_US; UL_OWD_DELTA_US; ADJ_DELAY
        (($log_to_file)) && printf '%s\n' "$header" > /tmp/cake-autorate/log_fifo
        [[ -t 1 ]] && printf '%s\n' "${header//;}"
}

So we left space pad console output so it's aligned.

So log file output is as it was, and console output looks like:

root@OpenWrt:~/cake-autorate# ./cake-autorate.sh
 DEBUG 2022-09-30-18:55:40 1664560540.696526 Starting CAKE-autorate 1.1.0
 DEBUG 2022-09-30-18:55:40 1664560540.697659 Down interface: ifb-dl (10000 / 25000 / 80000)
 DEBUG 2022-09-30-18:55:40 1664560540.698950 Up interface: ifb-ul (25000 / 30000 / 35000)
 DEBUG 2022-09-30-18:55:40 1664560540.700201 rx_bytes_path: /sys/class/net/ifb-dl/statistics/tx_bytes
 DEBUG 2022-09-30-18:55:40 1664560540.701299 tx_bytes_path: /sys/class/net/ifb-ul/statistics/rx_bytes
SHAPER 2022-09-30-18:55:40 1664560540.719314 tc qdisc change root dev ifb-dl cake bandwidth 25000Kbit
SHAPER 2022-09-30-18:55:40 1664560540.725801 tc qdisc change root dev ifb-ul cake bandwidth 30000Kbit
HEADER LOG_DATETIME LOG_TIMESTAMP PROC_TIME_US DL_ACHIEVED_RATE_KBPS UL_ACHIEVED_RATE_KBPS DL_LOAD_PERCENT UL_LOAD_PERCENT RTT_TIMESTAMP REFLECTOR SEQUENCE DL_OWD_BASELINE DL_OWD_US DL_OWD_DELTA_US UL_OWD_BASELINE UL_OWD_US UL_OWD_DELTA_US ADJ_DELAY_THR SUM_DL_DELAYS SUM_UL_DELAYS DL_LOAD_CONDITION UL_LOAD_CONDITION CAKE_DL_RATE_KBPS CAKE_UL_RATE_KBPS
  DATA 2022-09-30-18:55:40 1664560540.817450 1664560540.815733 0 0 0 0 1664560540.808860 1.1.1.1 0 70385 22650 -477350 70385 22650 -477350 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:40 1664560540.876824 1664560540.875753 0 0 0 0 1664560540.866900 1.0.0.1 0 72410 24900 -475100 72410 24900 -475100 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:40 1664560540.933202 1664560540.931156 0 0 0 0 1664560540.919850 8.8.8.8 0 73670 26300 -473700 73670 26300 -473700 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:40 1664560540.978332 1664560540.976964 11 15 0 0 1664560540.965950 8.8.4.4 0 71780 24200 -475800 71780 24200 -475800 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.031325 1664560541.029966 11 15 0 0 1664560541.016900 1.1.1.1 1 29178 24600 -45785 29178 24600 -45785 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.080168 1664560541.078353 11 15 0 0 1664560541.065930 1.0.0.1 1 28931 24100 -48310 28931 24100 -48310 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.133881 1664560541.129636 11 15 0 0 1664560541.116920 8.8.8.8 1 29417 24500 -49170 29417 24500 -49170 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.180465 1664560541.178645 15 24 0 0 1664560541.166000 8.8.4.4 1 28778 24000 -47780 28778 24000 -47780 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.234422 1664560541.232590 15 24 0 0 1664560541.219860 1.1.1.1 2 26227 25900 -3278 26227 25900 -3278 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.286153 1664560541.284337 15 24 0 0 1664560541.271860 1.0.0.1 2 26923 26700 -2231 26923 26700 -2231 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.329779 1664560541.326338 15 24 0 0 1664560541.318180 8.8.8.8 2 25261 24800 -4617 25261 24800 -4617 12966 0 0 dl_idle ul_idle 25000 30000
^C  INFO 2022-09-30-18:55:41 1664560541.391170
  INFO 2022-09-30-18:55:41 1664560541.394229 Killing all background processes and cleaning up /tmp files.
richb-hanover commented 2 years ago

I am going to leave it to you both to solve. My needs have been addressed (I was unhappy with the timestamp indentation jumping around).

Long term thoughts:

  1. We're in a period of experimentation now. We should plan on changes to the formatting and contents of the fields as our understanding of what's important changes.
  2. We almost certainly will develop/evolve tools that digest these files. The effort to "normalize" the data fields in those tools will not be significant, no matter what format we select.
  3. A year from now, the science will be settled. It'll be a rare occurrence that someone will care to look at the log files because cake-autorate will work so well. Whatever tools we created for 2) above will work as needed.

Thanks.

lynxthecat commented 2 years ago

Sorry I just edited my comment above - are you both happy with the new code:

# Send message to fifo for sending to log file w/ log file rotation check
log_msg()
{
        local type=$1
        local msg=$2

        (($log_to_file)) && printf '%s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg" > /tmp/cake-autorate/log_fifo
        [[ -t 1 ]] && printf '%6s %(%F-%H:%M:%S)T %s %s\n' "$type" -1 "$EPOCHREALTIME" "${msg//;}"
}

# Send message directly to log file wo/ log file rotation check (e.g. before maintain_log_file() is up)
log_msg_bypass_fifo()
{

        local type=$1
        local msg=$2

        (($log_to_file)) && printf '%s; %(%F-%H:%M:%S)T; %s; %s\n' "$type" -1 "$EPOCHREALTIME" "$msg" >> /tmp/cake-autorate.log
        [[ -t 1 ]] && printf '%6s %(%F-%H:%M:%S)T %s %s\n' "$type" -1 "$EPOCHREALTIME" "${msg//;}"

}

print_header()
{
        header="HEADER; LOG_DATETIME; LOG_TIMESTAMP; PROC_TIME_US; DL_ACHIEVED_RATE_KBPS; UL_ACHIEVED_RATE_KBPS; DL_LOAD_PERCENT; UL_LOAD_PERCENT; RTT_TIMESTAMP; REFLECTOR; SEQUENCE; DL_OWD_BASELINE; DL_OWD_US; DL_OWD_DELTA_US; UL_OWD_BASELINE; UL_OWD_US; UL_OWD_DELTA_US; ADJ_DELAY
        (($log_to_file)) && printf '%s\n' "$header" > /tmp/cake-autorate/log_fifo
        [[ -t 1 ]] && printf '%s\n' "${header//;}"
}

See my post above. So we zero-pad the first column and strip out semicolons for console output and leave log file handling as it was (save for CAKE-CHANGE replaced with SHAPER).

So console looks like:

root@OpenWrt:~/cake-autorate# ./cake-autorate.sh
 DEBUG 2022-09-30-18:55:40 1664560540.696526 Starting CAKE-autorate 1.1.0
 DEBUG 2022-09-30-18:55:40 1664560540.697659 Down interface: ifb-dl (10000 / 25000 / 80000)
 DEBUG 2022-09-30-18:55:40 1664560540.698950 Up interface: ifb-ul (25000 / 30000 / 35000)
 DEBUG 2022-09-30-18:55:40 1664560540.700201 rx_bytes_path: /sys/class/net/ifb-dl/statistics/tx_bytes
 DEBUG 2022-09-30-18:55:40 1664560540.701299 tx_bytes_path: /sys/class/net/ifb-ul/statistics/rx_bytes
SHAPER 2022-09-30-18:55:40 1664560540.719314 tc qdisc change root dev ifb-dl cake bandwidth 25000Kbit
SHAPER 2022-09-30-18:55:40 1664560540.725801 tc qdisc change root dev ifb-ul cake bandwidth 30000Kbit
HEADER LOG_DATETIME LOG_TIMESTAMP PROC_TIME_US DL_ACHIEVED_RATE_KBPS UL_ACHIEVED_RATE_KBPS DL_LOAD_PERCENT UL_LOAD_PERCENT RTT_TIMESTAMP REFLECTOR SEQUENCE DL_OWD_BASELINE DL_OWD_US DL_OWD_DELTA_US UL_OWD_BASELINE UL_OWD_US UL_OWD_DELTA_US ADJ_DELAY_THR SUM_DL_DELAYS SUM_UL_DELAYS DL_LOAD_CONDITION UL_LOAD_CONDITION CAKE_DL_RATE_KBPS CAKE_UL_RATE_KBPS
  DATA 2022-09-30-18:55:40 1664560540.817450 1664560540.815733 0 0 0 0 1664560540.808860 1.1.1.1 0 70385 22650 -477350 70385 22650 -477350 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:40 1664560540.876824 1664560540.875753 0 0 0 0 1664560540.866900 1.0.0.1 0 72410 24900 -475100 72410 24900 -475100 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:40 1664560540.933202 1664560540.931156 0 0 0 0 1664560540.919850 8.8.8.8 0 73670 26300 -473700 73670 26300 -473700 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:40 1664560540.978332 1664560540.976964 11 15 0 0 1664560540.965950 8.8.4.4 0 71780 24200 -475800 71780 24200 -475800 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.031325 1664560541.029966 11 15 0 0 1664560541.016900 1.1.1.1 1 29178 24600 -45785 29178 24600 -45785 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.080168 1664560541.078353 11 15 0 0 1664560541.065930 1.0.0.1 1 28931 24100 -48310 28931 24100 -48310 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.133881 1664560541.129636 11 15 0 0 1664560541.116920 8.8.8.8 1 29417 24500 -49170 29417 24500 -49170 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.180465 1664560541.178645 15 24 0 0 1664560541.166000 8.8.4.4 1 28778 24000 -47780 28778 24000 -47780 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.234422 1664560541.232590 15 24 0 0 1664560541.219860 1.1.1.1 2 26227 25900 -3278 26227 25900 -3278 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.286153 1664560541.284337 15 24 0 0 1664560541.271860 1.0.0.1 2 26923 26700 -2231 26923 26700 -2231 12966 0 0 dl_idle ul_idle 25000 30000
  DATA 2022-09-30-18:55:41 1664560541.329779 1664560541.326338 15 24 0 0 1664560541.318180 8.8.8.8 2 25261 24800 -4617 25261 24800 -4617 12966 0 0 dl_idle ul_idle 25000 30000
^C  INFO 2022-09-30-18:55:41 1664560541.391170
  INFO 2022-09-30-18:55:41 1664560541.394229 Killing all background processes and cleaning up /tmp files.

And log output looks like:

root@OpenWrt:~/cake-autorate# vi cake-autorate.sh
root@OpenWrt:~/cake-autorate# tail /tmp/cake-autorate.log
DATA; 2022-09-30-18:55:41; 1664560541.030293; 1664560541.029966; 11; 15; 0; 0; 1664560541.016900; 1.1.1.1; 1; 29178; 24600; -45785; 29178; 24600; -45785; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
DATA; 2022-09-30-18:55:41; 1664560541.079220; 1664560541.078353; 11; 15; 0; 0; 1664560541.065930; 1.0.0.1; 1; 28931; 24100; -48310; 28931; 24100; -48310; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
DATA; 2022-09-30-18:55:41; 1664560541.130503; 1664560541.129636; 11; 15; 0; 0; 1664560541.116920; 8.8.8.8; 1; 29417; 24500; -49170; 29417; 24500; -49170; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
DATA; 2022-09-30-18:55:41; 1664560541.179511; 1664560541.178645; 15; 24; 0; 0; 1664560541.166000; 8.8.4.4; 1; 28778; 24000; -47780; 28778; 24000; -47780; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
DATA; 2022-09-30-18:55:41; 1664560541.233465; 1664560541.232590; 15; 24; 0; 0; 1664560541.219860; 1.1.1.1; 2; 26227; 25900; -3278; 26227; 25900; -3278; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
DATA; 2022-09-30-18:55:41; 1664560541.285201; 1664560541.284337; 15; 24; 0; 0; 1664560541.271860; 1.0.0.1; 2; 26923; 26700; -2231; 26923; 26700; -2231; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
DATA; 2022-09-30-18:55:41; 1664560541.327310; 1664560541.326338; 15; 24; 0; 0; 1664560541.318180; 8.8.8.8; 2; 25261; 24800; -4617; 25261; 24800; -4617; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
DATA; 2022-09-30-18:55:41; 1664560541.385160; 1664560541.384291; 38; 18; 0; 0; 1664560541.370830; 8.8.4.4; 2; 26232; 25950; -2828; 26232; 25950; -2828; 12966; 0; 0; dl_idle; ul_idle; 25000; 30000
INFO; 2022-09-30-18:55:41; 1664560541.390180;
INFO; 2022-09-30-18:55:41; 1664560541.392516; Killing all background processes and cleaning up /tmp files.
root@OpenWrt:~/cake-autorate#
lynxthecat commented 2 years ago

@patrakov are you happy with the above?

richb-hanover commented 2 years ago

That looks fine to me.

Since print_header() duplicates a lot of the code of log_msg(), consider refactoring it as follows. You miss out on a label for the date-time and timestamp fields, but they're quite self-documenting. Thanks.

print_header()
{
    header="PROC_TIME_US; DL_ACHIEVED_RATE_KBPS; UL_ACHIEVED_RATE_KBPS; DL_LOAD_PERCENT; UL_LOAD_PERCENT; RTT_TIMESTAMP; REFLECTOR; SEQUENCE; DL_OWD_BASELINE; DL_OWD_US; DL_OWD_DELTA_US; UL_OWD_BASELINE; UL_OWD_US; UL_OWD_DELTA_US; ADJ_DELAY

    log_msg "HEADER" "$header"
}
patrakov commented 2 years ago

Looks acceptable.

moeller0 commented 2 years ago

You miss out on a label for the date-time and timestamp fields, but they're quite self-documenting.

These are not really optional labels.... to make sense each column in the de-interleaved DATA table should have a clear and unambiguous name....

richb-hanover commented 2 years ago

OK. Leave print_header() as it is. Thanks.

lynxthecat commented 2 years ago

So at the moment the only padding implemented in the latest code is the right space padding on the type field (first column below) so that the log date and time fields line up. I tested with and without and I think @richb-hanover is right to push for the initial padding in the type field.

But I'm not padding any of the remaining fields at the moment. This gives:

root@OpenWrt:~/cake-autorate# ./cake-autorate.sh
DEBUG  2022-10-01-15:49:07 1664635747.995082 Starting CAKE-autorate 1.1.0
DEBUG  2022-10-01-15:49:07 1664635747.996496 Down interface: ifb-dl (10000 / 25000 / 80000)
DEBUG  2022-10-01-15:49:07 1664635747.998457 Up interface: ifb-ul (25000 / 30000 / 35000)
DEBUG  2022-10-01-15:49:08 1664635747.999973 rx_bytes_path: /sys/class/net/ifb-dl/statistics/tx_bytes
DEBUG  2022-10-01-15:49:08 1664635748.002334 tx_bytes_path: /sys/class/net/ifb-ul/statistics/rx_bytes
SHAPER 2022-10-01-15:49:08 1664635748.021975 tc qdisc change root dev ifb-dl cake bandwidth 25000Kbit
SHAPER 2022-10-01-15:49:08 1664635748.028177 tc qdisc change root dev ifb-ul cake bandwidth 30000Kbit
HEADER LOG_DATETIME LOG_TIMESTAMP PROC_TIME_US DL_ACHIEVED_RATE_KBPS UL_ACHIEVED_RATE_KBPS DL_LOAD_PERCENT UL_LOAD_PERCENT RTT_TIMESTAMP REFLECTOR SEQUENCE DL_OWD_BASELINE DL_OWD_US DL_OWD_DELTA_US UL_OWD_BASELINE UL_OWD_US UL_OWD_DELTA_US ADJ_DELAY_THR SUM_DL_DELAYS SUM_UL_DELAYS DL_LOAD_CONDITION UL_LOAD_CONDITION CAKE_DL_RATE_KBPS CAKE_UL_RATE_KBPS
DATA   2022-10-01-15:49:08 1664635748.149385 1664635748.148386 0 0 0 0 1664635748.140150 1.1.1.1 0 83165 36850 -463150 83165 36850 -463150 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.197278 1664635748.196197 0 0 0 0 1664635748.188570 1.0.0.1 0 82310 35900 -464100 82310 35900 -464100 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.227401 1664635748.226025 0 0 0 0 1664635748.214550 8.8.8.8 0 71195 23550 -476450 71195 23550 -476450 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.277670 1664635748.276321 13 15 0 0 1664635748.265640 8.8.4.4 0 71645 24050 -475950 71645 24050 -475950 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.358613 1664635748.356805 13 15 0 0 1664635748.344570 1.1.1.1 1 42921 38450 -44715 42921 38450 -44715 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.413164 1664635748.411196 13 15 0 0 1664635748.398570 1.0.0.1 1 44501 40300 -42010 44501 40300 -42010 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.429670 1664635748.427870 13 15 0 0 1664635748.414650 8.8.8.8 1 28044 23250 -47945 28044 23250 -47945 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.479686 1664635748.477891 15 15 0 0 1664635748.465600 8.8.4.4 1 28494 23700 -47945 28494 23700 -47945 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.557570 1664635748.555768 15 15 0 0 1664635748.543550 1.1.1.1 2 38132 37600 -5321 38132 37600 -5321 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.606649 1664635748.604855 15 15 0 0 1664635748.592560 1.0.0.1 2 37660 36900 -7601 37660 36900 -7601 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.633722 1664635748.631879 15 15 0 0 1664635748.618550 8.8.8.8 2 25169 24850 -3194 25169 24850 -3194 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.678715 1664635748.676909 15 63 0 0 1664635748.663860 8.8.4.4 2 23054 22450 -6044 23054 22450 -6044 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.752713 1664635748.750803 15 63 0 0 1664635748.738610 1.1.1.1 3 35133 34800 -3332 35133 34800 -3332 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.798546 1664635748.796754 15 63 0 0 1664635748.784560 1.0.0.1 3 33061 32550 -5110 33061 32550 -5110 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.828830 1664635748.827018 15 63 0 0 1664635748.813580 8.8.8.8 3 22316 22000 -3169 22316 22000 -3169 12966 0 0 dl_idle ul_idle 25000 30000
DATA   2022-10-01-15:49:08 1664635748.878378 1664635748.876569 19 15 0 0 1664635748.863630 8.8.4.4 3 22105 22000 -1054 22105 22000 -1054 12966 0 0 dl_idle ul_idle 25000 30000
^CINFO   2022-10-01-15:49:08 1664635748.949521
INFO   2022-10-01-15:49:08 1664635748.951585 Killing all background processes and cleaning up /tmp files.

You see a challenge is that with padding to make all the remaining fields line up they become so separated that they won't fit on a single laptop screen anymore. In fact the above lines already wrap on my laptop.

So I intend to leave things like this, unless anyone has any further thoughts on this.

moeller0 commented 2 years ago

bigger question, for the console output does "2022-10-01-15:49:08" really contain useful information (that con not be recovered better from the log file)? If not we might be able to remove this field on the console so we see more of the relevant data?

lynxthecat commented 2 years ago

I reverted back to the old behaviour of same console and log file output. This may reflect a personal bias but it just seems cleaner to keep them the same. Closing for now but if anyone feels strongly please reopen.

richb-hanover commented 2 years ago

+1. I am glad to see the "; " separators back in the console output. It makes it easier to copy/paste console output into a spreadsheet. Thanks.