Logging Long-running Processes

In an earlier post I talked about getting the amount of time required for long-running processes - a simple approach to determining how much time remains in this batch sort of thing. That, of course, started me thinking...

What if I have a long-running process that is one in a series of long-running processes - how can I track that?

Let's say, for example, you're going to copy several repositories from one location to another, so you set up a small script to copy them - you might have several lines, each something like "cp <source> <destination>". What if, you wanted to track the process a little more closely and wanted other people or processes to also be able to see the progress?

First, you probably don't want to use an OS command - that won't give you enough information, so you set up a small script that will copy from the source to the destination, and since this is a long-running process you want to make sure you're writing information to a log that it's started (and you're going to include something that your other scripts can use to determine how much time remains). Now your (bash) script - the one you're going to use in your batch-process script - is looking something like this...

1. SOURCE="$1"
2. DESTINATION="$2"
4. LOG_FILE=`basename $0`
5. LOG_FILE="${LOG_FILE/.sh/.log}"
7. FILES=`ls -l $SOURCE | egrep '^-' | wc -l`
8. STARTED=`date "+%FT%T"`
10. LOG_ENTRY="$SOURCE\t$DESTINATION\t$STARTED\t$FILES"
12. echo -e "$LOG_ENTRY" |tee -a $LOG_FILE
14. cp $SOURCE $DESTINATION

Now your script will send output showing the source and destination as well as the number of files that will be copied to a log that other people and processes can read. This way when your batch file runs to copy all the repositories, the start of each copy will be recorded. That's something, at least.

Let's go a little further, though and say that you want to also record, in the same log file, not only the time the process started, but when it ended also. In that case, we're going to change the format of the log - let's insert a column between the STARTED column and the FILES column, and we need to add lines after the copy command to record the time the process ended and modify the log entry so that we're not parsing multiple lines for a single action. This gives us a script that looks like...

1. SOURCE="$1"
2. DESTINATION="$2"
4. LOG_FILE=`basename $0`
5. LOG_FILE="${LOG_FILE/.sh/.log}"
7. FILES=`ls -l $SOURCE | egrep '^-' | wc -l`
8. STARTED=`date "+%FT%T"`
10. LOG_ENTRY="$SOURCE\t$DESTINATION\t$STARTED\t\t$FILES"
12. echo -e "$LOG_ENTRY" |tee -a $LOG_FILE
14. cp $SOURCE $DESTINATION
16. ENDED=`date "+%FT%T"`
17. NEW_ENTRY="$SOURCE\t$DESTINATION\t$STARTED\t$ENDED\t$FILES"
19. sed -i.bak "s/$LOG_ENTRY/$NEW_ENTRY/" $LOG_FILE

A few notes: (1) notice line 10 has a delimitor for the blank column - that's necessary to simplify the log reader so we don't have to redefine the fourth column; (2) notice the ".bak" after the inline option for sed - that's necessary to ensure that some OSs, which require it, won't fail; and (3) if LOG_ENTRY or NEW_ENTRY contain a "/", be sure to escape them (or change sed's delimiter, which is probably easier).

Now, when your batch-process script invokes your process script, it will update the log with the SOURCE, DESTINATION, STARTED, and FILES entries when the process begins, and will update that log entry, inserting the ENDED value when the process ends.

You can use this approach to not only fine-tune your reporting and estimates, but this approach will also indicate, at a glance, which process(es) are still running...which could be even more value if the calls are asynchronous - but asynchronous calls are another topic altogether.

Happy coding.