Fix LOG_REQUEST_IDENTIFIERS not applying to Associaton send QR methods (

#936)

docs/changelog/v2.1.0.rst

@@ -12,6 +12,10 @@ Fixes
 * Fixed maximum length of *Patient ID* attribute in ``qrscp`` app (:issue:`785`)
 * Sanitise filenames for received datasets for non-conformant SOP Instance
  UIDs (:issue:`823`)
+* Fixed :attr:~pynetdicom._config.LOG_REQUEST_IDENTIFIERS` not applying to
+ meth:`Association.send_c_find()<pynetdicom.association.Association.send_c_find>`,
+ meth:`Association.send_c_move()<pynetdicom.association.Association.send_c_move>` and
+ meth:`Association.send_c_get()<pynetdicom.association.Association.send_c_get>` (:issue:`911`)
 
 
 Enhancements
@@ -40,4 +44,4 @@ Changes
 * Dropped support for Python 3.7, 3.8 and 3.9
 * Added support for Python 3.11 and 3.12
 * With `Python 3.10 requiring OpenSSL v1.1.1 or newer
- <https://peps.python.org/pep-0644/>`_, TLS v1.3 is now officially supported
+ <https://peps.python.org/pep-0644/>`_, TLS v1.3 is now supported

pynetdicom/association.py

@@ -1252,10 +1252,12 @@ def send_c_find(
 
  LOGGER.info(f"Sending Find Request: MsgID {msg_id}")
  LOGGER.info("")
- LOGGER.info("# Request Identifier")
- for line in pretty_dataset(dataset):
- LOGGER.info(line)
- LOGGER.info("")
+ if _config.LOG_REQUEST_IDENTIFIERS:
+ LOGGER.info("# Request Identifier")
+ for line in pretty_dataset(dataset):
+ LOGGER.info(line)
+
+ LOGGER.info("")
 
  # Pause the reactor to prevent a race condition
  self._reactor_checkpoint.clear()
@@ -1458,10 +1460,12 @@ def send_c_get(
 
  LOGGER.info(f"Sending Get Request: MsgID {msg_id}")
  LOGGER.info("")
- LOGGER.info("# Request Identifier")
- for line in pretty_dataset(dataset):
- LOGGER.info(line)
- LOGGER.info("")
+ if _config.LOG_REQUEST_IDENTIFIERS:
+ LOGGER.info("# Request Identifier")
+ for line in pretty_dataset(dataset):
+ LOGGER.info(line)
+
+ LOGGER.info("")
 
  # Pause the reactor to prevent a race condition
  self._reactor_checkpoint.clear()
@@ -1668,10 +1672,12 @@ def send_c_move(
 
  LOGGER.info(f"Sending Move Request: MsgID {msg_id}")
  LOGGER.info("")
- LOGGER.info("# Request Identifier")
- for line in pretty_dataset(dataset):
- LOGGER.info(line)
- LOGGER.info("")
+ if _config.LOG_REQUEST_IDENTIFIERS:
+ LOGGER.info("# Request Identifier")
+ for line in pretty_dataset(dataset):
+ LOGGER.info(line)
+
+ LOGGER.info("")
 
  # Pause the reactor to prevent a race condition
  self._reactor_checkpoint.clear()

pynetdicom/service_class.py

@@ -1364,7 +1364,7 @@ def validate_status(self, status: int | Dataset, rsp: _T) -> _T:
  # Failure: Cannot Understand - Unknown status returned by the
  # callback
  LOGGER.warning(
- f"Unknown status value returned by callback - " f"0x{rsp.Status:04X}"
+ f"Unknown status value returned by callback - 0x{rsp.Status:04X}"
  )
 
  return rsp
@@ -1897,10 +1897,9 @@ def _add_failed_instance(ds: Dataset) -> None:
 
  if _bulk_data:
  LOGGER.warning(
- f"The Query/Retrieve - Composite Instance "
- f"Retrieve Without Bulk Data service is "
- f"requested but a yielded dataset contains the "
- f"following (to be removed) bulk data "
+ "The Query/Retrieve - Composite Instance Retrieve "
+ "Without Bulk Data service is requested but a yielded "
+ "dataset contains the following (to be removed) bulk data "
  f"elements: {','.join(_bulk_data)}"
  )
 
@@ -1929,9 +1928,7 @@ def _add_failed_instance(ds: Dataset) -> None:
  f"0x{store_status_int:04X} ({store_status[0]})"
  )
  else:
- msg = (
- f"Get SCP: Received Store SCP response " f"({store_status[0]})"
- )
+ msg = f"Get SCP: Received Store SCP response ({store_status[0]})"
  LOGGER.info(msg)
 
  # Update the C-STORE sub-operation result tracker
@@ -2329,13 +2326,11 @@ def _add_failed_instance(ds: Dataset) -> None:
 
  if store_status_int is not None:
  msg = (
- f"Move SCP: Received Store SCP response "
+ "Move SCP: Received Store SCP response "
  f"0x{store_status_int:04X} ({store_status[0]})"
  )
  else:
- msg = (
- f"Move SCP: Received Store SCP response " f"({store_status[0]})"
- )
+ msg = f"Move SCP: Received Store SCP response ({store_status[0]})"
 
  LOGGER.info(msg)
 

pynetdicom/tests/test_assoc.py

@@ -93,6 +93,14 @@ def enable_unrestricted():
  _config.UNRESTRICTED_STORAGE_SERVICE = False
 
 
+@pytest.fixture
+def disable_identifer_logging():
+ original = _config.LOG_REQUEST_IDENTIFIERS
+ _config.LOG_REQUEST_IDENTIFIERS = False
+ yield
+ _config.LOG_REQUEST_IDENTIFIERS = original
+
+
 class DummyDIMSE:
  def __init__(self):
  self.status = None
@@ -2601,6 +2609,39 @@ def handle(event):
  )
  assert msg in caplog.text
 
+ def test_identifier_logging(self, caplog, disable_identifer_logging):
+ """Test identifiers not logged if config option set"""
+
+ def handle(event):
+ yield 0x0000, None
+
+ self.ae = ae = AE()
+ ae.acse_timeout = 5
+ ae.dimse_timeout = 5
+ ae.network_timeout = 5
+ ae.add_supported_context(PatientRootQueryRetrieveInformationModelFind)
+ scp = ae.start_server(
+ ("localhost", 11112), block=False, evt_handlers=[(evt.EVT_C_FIND, handle)]
+ )
+
+ ae.add_requested_context(PatientRootQueryRetrieveInformationModelFind)
+ assoc = ae.associate("localhost", 11112)
+ assert assoc.is_established
+
+ with caplog.at_level(logging.INFO, logger="pynetdicom"):
+ for status, ds in assoc.send_c_find(
+ self.ds, PatientRootQueryRetrieveInformationModelFind
+ ):
+ assert status.Status == 0x0000
+ assert ds is None
+
+ assoc.release()
+ assert assoc.is_released
+
+ scp.shutdown()
+
+ assert "(0010,0010) PN" not in caplog.text
+
 
 class TestAssociationSendCCancel:
  """Run tests on Association send_c_cancel."""
@@ -3665,6 +3706,63 @@ def handle_store(event):
 
  scp.shutdown()
 
+ def test_identifier_logging(self, caplog, disable_identifer_logging):
+ """Test identifiers not logged if config option set"""
+
+ def handle_get(event):
+ yield 2
+ yield 0xFF00, self.good
+ yield 0xFF00, self.good
+
+ def handle_store(event):
+ return 0x0000
+
+ scu_handler = [(evt.EVT_C_STORE, handle_store)]
+ scp_handler = [(evt.EVT_C_GET, handle_get)]
+
+ self.ae = ae = AE()
+ ae.acse_timeout = 5
+ ae.dimse_timeout = 5
+ ae.network_timeout = 5
+ ae.add_supported_context(PatientRootQueryRetrieveInformationModelGet)
+ ae.add_supported_context(CTImageStorage, scu_role=True, scp_role=True)
+
+ scp = ae.start_server(
+ ("localhost", 11112), block=False, evt_handlers=scp_handler
+ )
+
+ ae.add_requested_context(PatientRootQueryRetrieveInformationModelGet)
+ ae.add_requested_context(CTImageStorage)
+
+ role = build_role(CTImageStorage, scp_role=True, scu_role=True)
+
+ assoc = ae.associate(
+ "localhost", 11112, evt_handlers=scu_handler, ext_neg=[role]
+ )
+
+ assert assoc.is_established
+
+ with caplog.at_level(logging.INFO, logger="pynetdicom"):
+ result = assoc.send_c_get(
+ self.ds, PatientRootQueryRetrieveInformationModelGet
+ )
+ (status, ds) = next(result)
+ assert status.Status == 0xFF00
+ assert ds is None
+ (status, ds) = next(result)
+ assert status.Status == 0xFF00
+ assert ds is None
+ (status, ds) = next(result)
+ assert status.Status == 0x0000
+ assert ds is None
+
+ assoc.release()
+ assert assoc.is_released
+
+ scp.shutdown()
+
+ assert "(0010,0010) PN" not in caplog.text
+
 
 class TestAssociationSendCMove:
  """Run tests on Association send_c_move."""
@@ -4554,6 +4652,70 @@ def handle_move(event):
  )
  assert msg in caplog.text
 
+ def test_identifier_logging(self, caplog, disable_identifer_logging):
+ """Test identifiers not logged if config option set"""
+
+ def handle_store(event):
+ return 0x0000
+
+ self.ae = ae = AE()
+ ae.acse_timeout = 5
+ ae.dimse_timeout = 5
+ ae.network_timeout = 5
+
+ # Storage SCP
+ ae.add_supported_context(CTImageStorage)
+ store_scp = ae.start_server(
+ ("localhost", 11112),
+ block=False,
+ evt_handlers=[(evt.EVT_C_STORE, handle_store)],
+ )
+
+ # Move SCP
+ def handle_move(event):
+ yield "localhost", 11112
+ yield 2
+ yield 0xFF00, self.good
+
+ ae.add_requested_context(CTImageStorage)
+ ae.add_supported_context(PatientRootQueryRetrieveInformationModelMove)
+ ae.add_supported_context(StudyRootQueryRetrieveInformationModelMove)
+ ae.add_supported_context(PatientStudyOnlyQueryRetrieveInformationModelMove)
+ move_scp = ae.start_server(
+ ("localhost", 11113),
+ block=False,
+ evt_handlers=[(evt.EVT_C_MOVE, handle_move)],
+ )
+
+ # Move SCU
+ ae.add_requested_context(PatientRootQueryRetrieveInformationModelMove)
+ ae.add_requested_context(StudyRootQueryRetrieveInformationModelMove)
+ ae.add_requested_context(PatientStudyOnlyQueryRetrieveInformationModelMove)
+
+ assoc = ae.associate("localhost", 11113)
+ assert assoc.is_established
+
+ with caplog.at_level(logging.INFO, logger="pynetdicom"):
+ result = assoc.send_c_move(
+ self.ds, "TESTMOVE", PatientRootQueryRetrieveInformationModelMove
+ )
+ (status, ds) = next(result)
+ assert status.Status == 0xFF00
+ assert ds is None
+ (status, ds) = next(result)
+ assert status.Status == 0x0000
+ assert ds is None
+ with pytest.raises(StopIteration):
+ next(result)
+
+ assoc.release()
+ assert assoc.is_released
+
+ store_scp.shutdown()
+ move_scp.shutdown()
+
+ assert "(0010,0010) PN" not in caplog.text
+
 
 class TestGetValidContext:
  """Tests for Association._get_valid_context."""