Preserve context in spawned threads

[rconnaughton]

Is your feature request related to a problem? Please describe. Our application uses contextvars to include additional attributes in our log records, such as request ID (a la the logging cookbook example here). We would like all logs from our application to include this information so that we can quickly associate errors and such to other log lines. Unfortunately, when pynetdicom spawns threads for associations and the like, the context vars are not preserved, so log lines originating from your library can not be associated with the rest of our application logs.

Describe the solution you'd like We would like to see threads spawned by pynetdicom to preserve contextvars. I was able to proof-of-concept a partial fix by modifying dul.py so that the init records the context, and the thread executes within that context:

class DULServiceProvider(Thread):
  ....
  def __init__(...):
    from contextvars import copy_context
    self.ctx = copy_context()
    ...

  def run(self):
    self.ctx.run(super().run)

This would presumably have to be done in the various subclasses of Thread in your library, or some subset of them. We would be fine with this being always done, or opt-in behavior (but our own applications that use pynetdicom would always want this behavior)

Describe alternatives you've considered We have not found any suitable alternatives so far

Additional context Here is a bare-bones example app showing the issue.

import logging

from contextvars import ContextVar
from pynetdicom import AE
from pynetdicom.sop_class import CTImageStorage
from pydicom.uid import ImplicitVRLittleEndian

# Setup context var and log filter
request_id = ContextVar('request_id', default = '-')

def requestFilter(record):
  record.request_id = request_id.get()
  return True

# Configure logger to include request id
logging.basicConfig(level = logging.INFO, format = '%(asctime)s [%(levelname)s] <%(request_id)s> %(message)s')

for handler in logging.root.handlers:
  handler.addFilter(requestFilter)

logger = logging.getLogger('myapp')

# example handling a request in our service
request_id.set('my_example_id')
logger.info('starting association')
ae = AE()
ae.connection_timeout = 2
ae.add_requested_context(CTImageStorage, ImplicitVRLittleEndian)
assoc = ae.associate('1.1.1.1', 104)
logger.info('done')

Output:

# ./example.py 
2024-02-16 15:05:06,192 [INFO] <my_example_id> starting association
2024-02-16 15:05:06,193 [INFO] <my_example_id> Requesting Association
2024-02-16 15:06:21,195 [ERROR] <-> Association request failed: unable to connect to remote
2024-02-16 15:06:21,196 [ERROR] <-> TCP Initialisation Error: [Errno 111] Connection refused
2024-02-16 15:06:21,196 [INFO] <my_example_id> Aborting Association
2024-02-16 15:06:21,297 [INFO] <my_example_id> done

Output after just the dul.py modifications mentioned above:

# ./example.py 
2024-02-16 15:10:26,639 [INFO] <my_example_id> starting association
2024-02-16 15:10:26,641 [INFO] <my_example_id> Requesting Association
2024-02-16 15:10:28,644 [ERROR] <my_example_id> Association request failed: unable to connect to remote
2024-02-16 15:10:28,645 [ERROR] <my_example_id> TCP Initialisation Error: timed out
2024-02-16 15:10:28,646 [INFO] <my_example_id> Aborting Association
2024-02-16 15:10:28,746 [INFO] <my_example_id> done

[scaramallion]

Sounds good!