Debugging threads with logging

In [1]:

    

import logging
import random
import threading
import time

class Counter:
    
    def __init__(self, start=0):
        self.lock = threading.Lock()
        self.value = start

    def increment(self):
        logging.debug('Waiting for lock')
        self.lock.acquire()
        try:
            logging.debug('Acquired lock')
            self.value = self.value + 1
        finally:
            self.lock.release()

def worker(c):
    for i in range(2):
        pause = random.random()
        logging.debug('Sleeping %0.02f', pause)
        time.sleep(pause)
        c.increment()
    logging.debug('Done')


logging.basicConfig(
    level=logging.DEBUG,
    format='(%(threadName)-10s) %(message)s',
)

counter = Counter()
for i in range(2):
    t = threading.Thread(target=worker, args=(counter,))
    t.start()

logging.debug('Waiting for worker threads')
main_thread = threading.main_thread()
for t in threading.enumerate():
    if t is not main_thread:
        t.join()
logging.debug('Counter: %d', counter.value)


    

    




(Thread-4  ) Sleeping 0.12
(Thread-5  ) Sleeping 0.98
(MainThread) Waiting for worker threads
(Thread-4  ) Waiting for lock
(Thread-4  ) Acquired lock
(Thread-4  ) Sleeping 0.93
(Thread-5  ) Waiting for lock
(Thread-5  ) Acquired lock
(Thread-5  ) Sleeping 0.38
(Thread-4  ) Waiting for lock
(Thread-4  ) Acquired lock
(Thread-4  ) Done
(Thread-5  ) Waiting for lock
(Thread-5  ) Acquired lock
(Thread-5  ) Done






    




---------------------------------------------------------------------------
KeyboardInterrupt                         Traceback (most recent call last)
<ipython-input-1-da73bd883edc> in <module>
     42 for t in threading.enumerate():
     43     if t is not main_thread:
---> 44         t.join()
     45 logging.debug('Counter: %d', counter.value)

/usr/lib/python3.8/threading.py in join(self, timeout)
   1009 
   1010         if timeout is None:
-> 1011             self._wait_for_tstate_lock()
   1012         else:
   1013             # the behavior of a negative timeout isn't documented, but

/usr/lib/python3.8/threading.py in _wait_for_tstate_lock(self, block, timeout)
   1025         if lock is None:  # already determined that the C code is done
   1026             assert self._is_stopped
-> 1027         elif lock.acquire(block, timeout):
   1028             lock.release()
   1029             self._stop()

KeyboardInterrupt: 

In [ ]: