I am working with a legacy system that is not too bad, but I thought of making some improvements to it, and I wanted to solicit your feedback to help me make good decisions. The platform is Linix (different flavors of it).
The system revolves around running [sometimes long] “jobs” – command line programs. The jobs usually succeed but sometimes may fail, and when they do it is very important to diagnose what went wrong efficiently, and fix the underlying problems (if any) and restarting a job.
We are not using any third-party software for this because we need full control over the process. Right now information about a job is being saved on disk as files – there is one file for stdin, one file that stores the exit code, one file for stdout and stderr combined, and I also know exactly how the process was started – what was the name of the command and what were the arguments.
Now … I thought about splitting stdout and stderr outputs into different files, but then realized that when they are combined together, one can see the chronological order of messages, except that it now takes a human judgement to tell which was output and which contains the errors. Taking this to a further extreme – why not throw stdin into the mix? It might matter for debugging purposes what the specific line of input was that caused a failure. Ideally the error message would be descriptive enough to give plenty of context, but this does not always happen.
I am looking for a clean way to organize this data so that automated logic could be used to aid humans with error diagnostics. With many jobs running these failures do happen rather often. An example of something that I might want to query for – what were the last 20 lines of input that preceded the first line in stderr? I suppose the exact time stamp can be useful, but not that critical. Also, since a logging module is being used, often the output lines already contain time stamps, but not always – I did not write every bit of this legacy system. I can make changes to it; I just do not want to rewrite it.
Could you propose a good way to massage these streams (add some sort of metadata perhaps) to organize things cleanly? The requirement is that not much extra computing power or disk / ram space should be utilized. I suspect that my problem is not unique. Thanks in advance.
2
When I’ve had to do this, I’ve always used a single logfile with “source-and-time” stamps.
Although this can be very useful, there is still the problem that STDOUT is normally buffered, whereas STDERR is normally not. This means that in looking at a combined log of tagged output lines, adjacent lines may not have happened anywhere near each other in time. You can un-buffer STDOUT, but this can introduce a Heisenberg effect so that the program succeeds/fails in different ways.
My solution is to make sure that any calls to log STDERR always flush STDIN first. Yes, this still has a bit of a Heisenberg effect, but it normally is not too bad.
Regarding STDIN: you can store them in the same common log file and during a test run just look for the next line tagged STDIN. You can even use this to do regression testing in that log files from 2 runs should be equivalent (ignoring time).