How to get logging messages as they're printed

[drewejohnson]

I've found that when I run ARMI on a remote machine behind a SLURM scheduler, the runLog messages don't get printed until the very end of the job. Some warnings that are raised by other python modules do get printed almost immediately however. This means I don't really have a way to check the status of an ARMI run until it's done.

I don't seem to have these issues with other python applications using standard print and logging functions. Does ARMI do something with the stdout stream that might be causing some of this behavior?

[youngmit]

We do a bunch of stuff to redirect standard out and error in runLog.py, especially when running with MPI. The main thing that might be surprising is when using MPI, each rank gets its own file to write to in the logs directory. At the end of the run, these are all stitched together into one file. For more details, see the startLog() function in the PrintLog() class.

We have been wondering for a while if some of this stuff is a bit to bespoke/over-wraught, and if it might make more sense to move over to more standardized logging libraries or the like, but haven't gotten to it. A couple of things that we would be really excited to be able to do with something more solid:

• per-module logging verbosity (this would let us get more detail out of a feature that we are debugging without having to turn on full debug logging and get hit with a firehose)
• more reliable/better buffered/appropriately tee'd output (this would likely solve your issue)

We would welcome and support any efforts along these lines :D

[drewejohnson]

So in this case, I wasn't running any MPI cases and was very confused why the log was still delayed. Looking through runLog into context pointed me to this section

armi/armi/context.py

Lines 96 to 98 in bb1d08d

	# Set batch mode if not a TTY, which means you're on a cluster writing to a stdout file
	# In this mode you cannot respond to prompts or anything
	CURRENT_MODE = Mode.INTERACTIVE if sys.stdout.isatty() else Mode.BATCH

which reminded me that the stdout isn't a stream in my case, but a file. So maybe the redirected stdout in my case has a very large buffer size? Otherwise it should eventually flush and write. But things like a warning message raised by other libraries are still written to the stdout before ARMI flushes the stream...

Kind of like your point on

more reliable/better buffered/appropriately tee'd output

maybe periodic calls to

armi/armi/runLog.py

Lines 138 to 140 in bb1d08d

	def flush(self):
	self._errStream.flush()
	self._outputStream.flush()

could help? But likely don't want to flush every time a message is emitted. Could check the amount of data in the buffer with something like self._outputStream.tell()

[youngmit]

Hmm... it could be something to do with buffering. The strange thing though is that in non-MPI contexts, the PrintLog just print()s in _emit(), and as far as I can tell, should still have sys.stdout pointing to its original stream. Might be worth instrumenting some of the init stuff to make sure that sys.stdout isn't in fact getting redirected.

[youngmit]

Also worth noting that from what I can tell, runLog is being kind of crude in that it grabs the global standard out and redirects it; so what is really strange is that any other module printing anything else would behave differently than the ARMI log stuff, since at the end of the day, everyone is just print()ing...🤔

[drewejohnson]

Definitely thinking buffering has something to do with it given that python -u did the trick. But I agree that it's still strange that other messages come through first w/o this switch.

It looks like the messages that come through come through other calls to logging messages not print statements. These logging calls go to the "real" stdout, while prints go to sys.stdout

>>> import sys, logging
>>> logging.warning("Test")
WARNING:root:Test
>>> print("Test")
Test
>>> fh = open("buffer", "w")
>>> sys.stdout = fh
>>> logging.warning("Test")
WARNING:root:Test
>>> print("test")
# nothing
>>> fh.close()

Even if we switch stdout before making a logger, they still go through to the "real" stdout

>>> import sys
>>> fh = open("buf", "w")
>>> sys.stdout = fh
>>> import logging
>>> logging.basicConfig()
>>> logging.warning("test")
WARNING:root:test
>>> fh.close()

🤷‍♂️

[ntouran]

What happens if you invoke armi with a python -u execution argument? That forces it to run in unbuffered mode, which is how we usually submit things.

[drewejohnson]

That did it! Messages come through as they're logged