[MRG] Fix LOG_REQUEST_IDENTIFIERS not applying to Associaton send QR methods

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."""