sconscript.log does not capture logs from multiple scripts

[zhizhongpu]

Issue demo: 4ab2405. To reproduce, go to this commit and run scons --clean && scons

Issue description:

Note that under the set-up above, we have two scripts which run sequentially to produce outputs under output/derived/wb_clean:

• source/derived/wb_clean/build.py, which
  • takes more than 17 seconds
  • produces gdp_education.csv
  • prints "File 'output/derived/wb_clean/gdp_education.csv' saved successfully."
• source/derived/wb_clean/takelogs.do, which
  • takes in gdp_education.csv
  • takes 2 seconds
  • prints a bunch of (arguably useless) Stata logs like the below

  ___  ____  ____  ____  ____ ®
 /__    /   ____/   /   ____/      StataNow 19.5
___/   /   /___/   /   /___/       MP—Parallel Edition

The problem is that output/derived/wb_clean/sconscript.log only contains the Stata print-outs. Also, the time stamps reflect only the time taken by the .do file.

This has two downsides. First, a user may be interested in keeping track of warnings / print-outs from the first script; second, a user may be interested in the runtime of the first script. The current set-up does not suppose these uses.

I suspect that the underlying problem is that each script has its own sconscript.log, but the later one overwrites the earlier one. I think we might be able to change the builder so that sconscript.logs append to, instead of overwrite, each other.

fyi @jmshapir @liaochris

[liaochris]

@zhizhongpu are we able to solve this issue without script-specific sconscript.logs

• I'm worried appending still creates the issue that multiple files will write to the same log, and the log won't be clear if it's recording outputs by multiple scripts within a folding running in parallel
  • In such cases we might also run into race conditions that cause information to be overwritten

Also, this doesn't seem like an uncommon issue and I wonder how others who use scons approach logging.

[liaochris]

@zhizhongpu I'm not sure there's an easy solution to this without getting into scons internals, see SCons/scons#1183

[zhizhongpu]

per meeting: first think about the ideal behavior of scons logging. Then think about the implementation.

[zhizhongpu]

per meeting: first think about the ideal behavior of scons logging.

I think my preference is to have a (separate) log file for every R/STATA/Python/Matlab/Lyx/LaTex script that runs. That way we also know

1. when the script was last run
   • Recall that sometimes we accidentally forget to include a script into the scons structure, and this mistake would be easier to spot when we have separate, time-stamped logfile for each script we run
2. what the script-specific runtime is
   • This would be an improvement from the current set-up, which only shows output-folder-specific timestamps (hence Modify builders to routinely output more granular timestamps #96)
3. that parallelizing scripts won't write into the same logfile (which sometimes leads to incomplete logging)
4. what the latest log is for each script is, regardless of whether another script ran after it
   • This facilitates catching errors / warnings, because in the current set-up we could have an earlier script generating some nonfatal e.g. failure-to-converge warnings that get logged but overwritten by a later script's log
5. precisely which log file is produced by which script
   • Under the current set-up, we have sconscript.log produced in the output folder, which sometimes doesn't 100% follow the structure of the source script
6. that all logfiles will be git-tracked, instead of being in the datastore (which makes it harder to trace the evolution of the logfile)

I have a conceptual implementation plan, which is to create a structure of

• source/
• output/
• sconslog/

where sconslog/ mirrors 100% the folder structure of source, and each script source/ABC/jkl.xyz produces sconslog/ABC/jkl.log in a scons run.

@liaochris @jmshapir thoughts?

[jmshapir]

@zhizhongpu thanks!

This seems worth thinking through.

Imagine a structure where all we track is:

• last start time
• last end time
• success flag

How much do you think this would lose, and would the loss be outweighed by the simplicity of scanning/diffing the simplified/structured information above?

[liaochris]

@jmshapir On #139 (comment) - my take is that the main benefit of the log is knowing how a script failed. We already know from scons when a script fails.

[jmshapir]

@liaochris I'm going to moderate your post above (and keep the modified version below) as it references an external non-public repository.

@zhizhongpu Conceptually, I think the plan is sound. I have two thoughts

• I agree with tracking runtime in some way, but as a reviewer, I think it might be distracting to see many file diffs in the log files where the runtime changes slightly, especially if it causes one to miss substantive changes in the log files. Since scons --debug=time also tracks runtime for us, and I have a script we can use to parse the scons runtime output, I'd be inclined to not include this part in sconslog
• Is it possible for the log to only display the bug if the script fails, as opposed to the whole output? I'm not inclined to have the log display the whole output.

[zhizhongpu]

@liaochris I'm going to moderate your post above

@jmshapir the sender can always transmit using an encrypted signal structure :-)

[jmshapir]

@jmshapir On #139 (comment) - my take is that the main benefit of the log is knowing how a script failed.

@liaochris meaning you think the runtime information isn't very useful?

On the "how it failed," I guess we could adapt my list above to something like:

• last start time
• last end time
• success flag
• error message (or last few lines of terminal output) in the event of failure

[liaochris]

@jmshapir Thanks! I mean two things

1. We already have a couple of tools (RC run logs telling us whether a run completed, the scons build log - which is separate from sconscript.log) that tell us about whether a script failed to run, so we don't need the success flag in the log unless we want to build in extra redundancy.

2. For pretty much every task except for runtime-related optimization, I don't find runtime to be useful. Since runtime isn't used very often, I don't think it makes sense to have runtime diffs show up in logs, especially in tasks where runtime optimization is not one of the primary objectives. Instead, I think a more elegant solution would be to
   a) Use scons native features to track runtime
   b) Store runtime information in a single file

[jmshapir]

@liaochris thanks!

Once we have @zhizhongpu's answer to #139 (comment) we can perhaps plan to discuss and decide if we want to make a change here.

[zhizhongpu]

@zhizhongpu thanks!

This seems worth thinking through.

Imagine a structure where all we track is:

• last start time
• last end time
• success flag
• error message (or last few lines of terminal output) in the event of failure

How much do you think this would lose, and would the loss be outweighed by the simplicity of scanning/diffing the simplified/structured information above?

I like the simple design, but I'm not very confident that I could forecast the potential impact of logging less.

The biggest downside would be that we lose track of (non-fatal) warnings. In my experience, tracking warnings can be more helpful where we need to confirm convergence. If left to me, I would keep the warnings both to keep track of them, and to pressure myself to find a way to address them so that they disappear (either get addressed or get muted) soon. On the other hand, given that in this lab, people seem not as bothered by warnings as I am, there's less value in tracking warnings. I think it could be fine to not track the warnings, conditional on whoever assigned to the NUMERICAL production task to be extra careful with potential convergence failures.

Sorry if that's not very helpful @jmshapir!

[zhizhongpu]

On some other matters:

• re: sconscript.log does not capture logs from multiple scripts #139 (comment) I understand that runtime isn't super important most of the times. I think tracking when a script / part of the pipeline was last run might be more useful than generally tracking runtime
• re: the below. I think in case a script runs into error it'd be helpful to know the full log, not just the last few lines of it / the immediate error, especially in LaTex, Python, and Lyx.

error message (or last few lines of terminal output) in the event of failure