debug(bklog):Debugging duration code

[EVA-2020-02.git] / exec / bklog-plan.org

* bklog task list
** TODO Adjust filename duration dynamically
2020-07-12T21:17Z; bktei> Currently, the "duration" component of the
output filename for a given chunk is calculated from the ~bufferTTL~
variable which does not necessarily reflect the amount of buffer lines
being read into a given chunk, especially since lines of stdin may be
received while synchronous processing occurs before a new
~magicProcessWriteBuffer &~ job is spun off.

A better way to specify the duration is to maintain a pair of
timestamp varriables before each ~magicProcessWriteBuffer~ command is
run. Within the asynchronous write job the time difference between the
two time stamps may be evaluated in order to determine how much time
has passed since the last write operation started. The last line read
into the buffer when the ~while read~ loop finishes should be the most
current value and so one of the two timestamps should be recorded
then. The other time stamp should simply be the previous loop's
timestamp value.

For example:

#+BEGIN_EXAMPLE
    # MAIN LOOP: Run until script TTL seconds pass
    bufferRound=0;
    while [[ $SECONDS -lt "scriptTTL" ]]; do
	vbm "STATUS:$fn:Starting buffer round:$bufferRound";
	bufferTOD="$((SECONDS + bufferTTL))"; # Set buffer round time-of-death
	# Consume stdin to fill buffer until buffer time-of-death (TOD) arrives
	while read -r -t "$bufferTTL" line && [[ $SECONDS -lt "$bufferTOD" ]]; do
	    # Append line to buffer array
	    buffer+=("$line");
	done;
        #====BEGIN NEW CODE HERE====
        bufferTimestampOld="$bufferTimestampNew";
        bufferTimeStampNew="$(date --iso-8601=seconds)";
        #====END NEW CODE HERE====
	# Create dir_tmp if missing
	if ! [[ -d "$dir_tmp" ]]; then
	    yell "ERROR:$fn:dir_tmp existence failure:$dir_tmp";
	    try mkdir "$dir_tmp" && vbm "DEBUG :$fn:Working dir recreated dir_tmp:$dir_tmp"; fi
	# Update cmd_encrypt, cmd_encrypt_suffix
	magicParseRecipients;
	# Export buffer to asynchronous processing.
	magicProcessWriteBuffer &
	unset buffer; # Clear buffer array for next bufferRound
	# Increment buffer round
	((bufferRound++));
    done;
#+END_EXAMPLE

Then, within the ~magicProcessWriteBuffer()~ function, the difference
in seconds between ~bufferTimestampOld~ and ~bufferTimestampNew~ may
be calculated and an appropriate duration string generated from the
~timeDuration()~ function.

** TODO Update ~SECONDS~ variable during while read loop
2020-07-14T00:58Z; bktei> The starting timestamps of each output file
still drifts against system time. Although the ~while read~ loop does
not lose data, the drift causes the output files to be named weirdly.

A possible solution is to correct the ~SECONDS~ variable against the
current system time. Because ~date~ calls are slow, this correction
should not be made after every line. At a minimum, the correction
should occur once per buffer round, possibly after the buffer round
has completed. If more frequent corrections are required, then the
number of lines being read in each buffer round should be tracked and
a modulus comparison may be implemented within the ~while read~ loop
so that a correction is made after some fraction of the expected lines
to be read are read.
** TODO Account for "early-exit" bug in input script
2020-07-14T03:00Z; bktei> What happens if the script piping its stdout
into ~bklog~ immediately exits without providing any stdout (ex: a
python script with a missing module)? ~bklog~ should be able to detect
the latest exit code and exit early. It should also be able to detect
if the incoming pipe is closed.
* bklog narrative