How to print log messages from external modules to the main Python module's terminal window?

Question

I am writing a Python command line program.

There is a main Python script file, acting as the entry point. When user run this script, it will execute a few external Python script files. The external Python script files may also execute other external Python script files. The number of external files is variable.

The Python script will execute external Python scripts using:

p = subprocess.Popen(args)

or

p = subprocess.call(args)

When I run the main Python script in a terminal window, it will print real time log messages on the screen when it is running. Now, I would like to get all log messages from all external Python scripts called by the main Python script and print it onto the same terminal window (the terminal window that I use to run the main script).

For example, below are the sequence of script execution:

1.Main-script
    |
    2.Layer-1-script-1
        |
        3.Layer-2-script-1
        |
        4.Layer-2-script-2
        |
    5.Layer-1-script-2
    |
    6.Layer-1-script-3
    |
7.Main-script(continued)

When I run the main script in a terminal window, is it possible that I can get real time log messages on my terminal window like below?

[time-hh-mm-ss][log message from main script]Script is running..
[time-hh-mm-ss][log message from main script]Calling script layer-1-script-1..
[time-hh-mm-ss][log message from layer-1-script-1]Script is running..
[time-hh-mm-ss][log message from layer-1-script-1]Calling script layer-2-script-1..
[time-hh-mm-ss][log message from layer-2-script-1]Script is running..
[time-hh-mm-ss][log message from layer-2-script-1]Calling script layer-2-script-2..
[time-hh-mm-ss][log message from layer-2-script-2]Script is running..
[time-hh-mm-ss][log message from layer-2-script-2]Calling script layer-1-script-2..
[time-hh-mm-ss][log message from layer-1-script-2]Script is running..
[time-hh-mm-ss][log message from layer-1-script-2]Calling script layer-1-script-3..
[time-hh-mm-ss][log message from layer-2-script-3]Script is running..
[time-hh-mm-ss][log message from main script]Back to main script. Script is running..

Is it possible that I can get a real time log messages like above in the terminal window?

Do you have control over all the python scripts (i.e. can you edit them?) or do you only control the main script? — unutbu, Sep 13 '12 at 14:59

score 0 · Answer 1 · answered Sep 13 '12 at 15:05

If you rely on the subprocess module, then you can only communicate via subprocess.PIPEs in order to collect the standard output and standard error from the subprocesses. Hence, make the subprocesses write their logging output to stdout/err and connect the subprocesses via pipes to the parent process. By doing so you can basically make the subprocess' stdout being printed to the parent process' stdout.

unutbu · Accepted Answer · 2012-09-13T15:38:02.830

If you have control over all the Python scripts, then you could use multiprocessing instead of subprocess with which you could do something like this:

test.py:

import logging
import test2
import multiprocessing as mp

logger = mp.get_logger()

def main():
    logger.info('Script is running')
    logger.info('Calling script test2')
    proc = mp.Process(target = test2.main)
    proc.start()
    proc.join()

if __name__ == '__main__':
    formatter = logging.Formatter('[%(asctime)s] [%(filename)s]: %(message)s',
                                  datefmt = '%H:%M:%S')
    handler = logging.StreamHandler()
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    logger.setLevel(logging.INFO)    
    main()

test2.py:

import multiprocessing as mp

logger = mp.get_logger()

def main():
    logger.info('Script is running...')

Running test.py yields

[11:36:50] [test.py]: Script is running
[11:36:50] [test.py]: Calling script test2
[11:36:50] [util.py]: child process calling self.run()
[11:36:50] [test2.py]: Script is running...
[11:36:50] [util.py]: process shutting down
[11:36:50] [util.py]: process exiting with exitcode 0
[11:36:50] [util.py]: process shutting down

When using `multiprocessing`, one should use `multiprocessing.get_logger()`. If the opener takes this way, he should also read http://stackoverflow.com/questions/641420/how-should-i-log-while-using-multiprocessing-in-python — Dr. Jan-Philip Gehrcke, Sep 13 '12 at 15:11
@Jan-PhilipGehrcke: Good point, thanks! I've edited the post. — unutbu, Sep 13 '12 at 15:38

How to print log messages from external modules to the main Python module's terminal window?

2 Answers2