By Brian Fitzgerald

Here are a few notes on cleaner-looking python logging messages. Some package defaults lead to verbose, ragged looking output.

from threading import Thread
from logging import debug, info, warning, error, critical
from logging import DEBUG, basicConfig
def hello():
    warning('Something is up')
basicConfig(level=DEBUG,
            format='%(asctime)s %(levelname)s %(threadName)s %(message)s'
            )
debug('begin')
error('problem')
critical('danger')
threads = []
for i in [1, 2]:
    th = Thread(target=hello)
    th.start()
    threads.append(th)
for th in threads:
    th.join()
    info('joined')
info('done')

"C:\Users\Brian Fitzgerald\PycharmProjects\blog\venv\Scripts\python.exe" "C:/Users/Brian Fitzgerald/PycharmProjects/blog/threadlogging.py"
2018-05-03 21:12:51,098 DEBUG MainThread begin
2018-05-03 21:12:51,099 ERROR MainThread problem
2018-05-03 21:12:51,099 CRITICAL MainThread danger
2018-05-03 21:12:51,099 WARNING Thread-1 Something is up
2018-05-03 21:12:51,100 WARNING Thread-2 Something is up
2018-05-03 21:12:51,100 INFO MainThread joined
2018-05-03 21:12:51,100 INFO MainThread joined
2018-05-03 21:12:51,100 INFO MainThread done

Process finished with exit code 0

Notes:

• The timestamp field is 23 characters
• The level field is 4 to 8 characters
• The thread identifier in this example is up to 10 characters
• The logger prefix requires up to 43 characters
• The content has a ragged appearance

Next, we will make three changes

1. use datefmt for a shorter date string: %Y%m%d.%H%M%S
2. use single character abbreviations for level: D, I, W, E, and C
3. format short, fixed-width thread identifiers using th%02d

from threading import Thread, currentThread
from logging import debug, info, warning, error, critical
from logging import DEBUG, basicConfig, addLevelName
def hello():
    warning('Something is up')
basicConfig(
    level=DEBUG,
    datefmt='%Y%m%d.%H%M%S',
    format='%(asctime)s %(levelname)s %(threadName)s %(message)s')
currentThread().setName('main')
addLevelName(10, 'D')
addLevelName(20, 'I')
addLevelName(30, 'W')
addLevelName(40, 'E')
addLevelName(50, 'C')
debug('begin')
error('problem')
critical('danger')
threads = []
for i in [1, 2]:
    th = Thread(target=hello)
    th.setName('th%02d' % i)
    th.start()
    threads.append(th)
for th in threads:
    th.join()
    info('joined')
info('done')

"C:\Users\Brian Fitzgerald\PycharmProjects\blog\venv\Scripts\python.exe" "C:/Users/Brian Fitzgerald/PycharmProjects/blog/threadlogging.py"
20180503.211759 D main begin
20180503.211759 E main problem
20180503.211759 C main danger
20180503.211759 W th01 Something is up
20180503.211759 W th02 Something is up
20180503.211759 I main joined
20180503.211759 I main joined
20180503.211759 I main done

Process finished with exit code 0

Now, each log file entry has a fixed 22-character width. There is more space to the right for the actual content.

By Brian Fitzgerald

Here are some notes on the behavior of python functions sys.exit() vs os._exit() in a threaded program.

from threading import Thread, currentThread
from time import sleep, time
import sys
import atexit

def pt(str=None):
    print('el=%ss th=%s: %s' % (
        round(time() - t0, 1),
        currentThread().name, str)
          )

def testexit():
    pt('sleeping')
    sleep(int(currentThread().getName()))
    pt('calling sys.exit')
    sys.exit(0)
    pt('returning')

def alldone():
    pt('all done')

t0 = time()
atexit.register(alldone)
threads = []
for i in [1, 2]:
    th = Thread(target=testexit)
    th.setName(i)
    th.setDaemon(False)
    th.start()
    threads.append(th)
for th in threads:
    pt('waiting to join thread th=%s' % th.name)
    th.join()
    pt('main: joined to th=%s' % th.name)

In the threads, the sleep time equals the thread id, i.e. 1 or 2 seconds. We have arranged that function alldone will execute when the program exits.

"C:\Users\Brian Fitzgerald\PycharmProjects\blog\venv\Scripts\python.exe" "C:/Users/Brian Fitzgerald/PycharmProjects/blog/threadexit.py"
el=0.0s th=1: sleeping
el=0.0s th=2: sleeping
el=0.0s th=MainThread: waiting to join thread th=1
el=1.0s th=1: calling sys.exit
el=1.0s th=MainThread: main: joined to th=1
el=1.0s th=MainThread: waiting to join thread th=2
el=2.0s th=2: calling sys.exit
el=2.0s th=MainThread: main: joined to th=2
el=2.0s th=MainThread: all done
Process finished with exit code 0

Notes:

• sys.exit() causes the thread to exit
• statement “pt(‘returning’)” is not reached
• The main thread finishes
• Function alldone is executed
• The output is identical if th.setDaemon(True)

Now changing “import sys” to “import os”, and “sys.exit(0)” to “os._exit(0)”:

from threading import Thread, currentThread
from time import sleep, time
import os
import atexit

def pt(str=None):
    print('el=%ss th=%s: %s' % (
        round(time() - t0, 1),
        currentThread().name, str)
          )

def testexit():
    pt('sleeping')
    sleep(int(currentThread().getName()))
    pt('calling os._exit')
    os._exit(0)
    pt('returning')

def alldone():
    pt('all done')

t0 = time()
atexit.register(alldone)
threads = []
for i in [1, 2]:
    th = Thread(target=testexit)
    th.setName(i)
    th.setDaemon(False)
    th.start()
    threads.append(th)

for th in threads:
    pt('waiting to join thread th=%s' % th.name)
    th.join()
    pt('main: joined to th=%s' % th.name)

"C:\Users\Brian Fitzgerald\PycharmProjects\blog\venv\Scripts\python.exe" "C:/Users/Brian Fitzgerald/PycharmProjects/blog/threadexit.py"
el=0.0s th=1: sleeping
el=0.0s th=2: sleeping
el=0.0s th=MainThread: waiting to join thread th=1
el=1.0s th=1: calling os._exit

Process finished with exit code 0

Notes:

• MainThread is terminated while waiting to join thread 1.
• thread 2 is terminated while sleeping
• alldone is not reached
• The output is identical if th.setDaemon(True)

Beware that os._exit can terminate a thread while it is in an exception handler:

def testexit():
    pt('try')
    try:
        raise Exception()
    except:
        pt('sleeping')
        sleep(int(currentThread().getName()))
        pt('done except')
    finally:
        pt('done finally')
    pt('calling os._exit')
    os._exit(0)
    pt('returning')

"C:\Users\Brian Fitzgerald\PycharmProjects\blog\venv\Scripts\python.exe" "C:/Users/Brian Fitzgerald/PycharmProjects/blog/threadexit.py"
el=0.0s th=1: try
el=0.0s th=1: sleeping
el=0.0s th=MainThread: waiting to join thread th=1
el=0.0s th=2: try
el=0.0s th=2: sleeping
el=1.0s th=1: done except
el=1.0s th=1: done finally
el=1.0s th=1: calling os._exit

Process finished with exit code 0

Note:

• In thread 2, pt(‘done except’) is not reached.

os._exit can also interrupt a finally block:

def testexit():
    pt('try')
    try:
        raise Exception()
    except:
        pt('done except')
    finally:
        pt('sleeping')
        sleep(int(currentThread().getName()))
        pt('done finally')
    pt('calling os._exit')
    os._exit(0)
    pt('returning')

"C:\Users\Brian Fitzgerald\PycharmProjects\blog\venv\Scripts\python.exe" "C:/Users/Brian Fitzgerald/PycharmProjects/blog/threadexit.py"
el=0.0s th=1: try
el=0.0s th=1: done except
el=0.0s th=1: sleeping
el=0.0s th=2: try
el=0.0s th=2: done except
el=0.0s th=MainThread: waiting to join thread th=1
el=0.0s th=2: sleeping
el=1.0s th=1: done finally
el=1.0s th=1: calling os._exit

Process finished with exit code 0

Note:

• In thread 2, pt(‘done finally’) is not reached