Repository: pydicom/pynetdicom

Issue:
Uncontrolled Logging of PHI in Pynetdicom
**Description:**
During our experimentation with Pynetdicom, specifically in conjunction with a local PACS server, we encountered an issue related to the retrieval of PatientId and PatientName. Upon inspection of the logs, we observed that the returned data is automatically logged without an available option to control or customize this logging behavior. This poses a dual challenge of potentially exposing sensitive patient information (PHI) through logging and the necessity for comprehensive logs for debugging purposes.

**Feature Request:**
We propose the implementation of an option to control the fields or logs that are printed during data retrieval. This enhancement would empower users of the association file to determine which information is logged, aligning with their specific usage requirements.

**Suggested Solution:**
We suggest the incorporation of an option that allows users to control the fields or logs to be printed during data retrieval. This could be achieved through one of the following alternatives:

_Flag in Logging Function:_
Introduce a flag within the relevant function (e.g., send_c_move) that enables/disables logging for specific data. This provides a convenient on/off switch for logging within the function.

_Field-Specific Control:_
Implement a mechanism that allows users to specify the fields they want to log, while ignoring others. This provides a more granular control over the information captured in the logs.

**Additional Information:**
This feature would enhance the overall security and usability of Pynetdicom by allowing users to strike a balance between logging essential information and safeguarding sensitive patient data. We believe that providing such control aligns with best practices for maintaining both privacy and debugging capabilities.

Discussion:
codecov[bot]: ## [Codecov](https://app.codecov.io/gh/pydicom/pynetdicom/pull/936?dropdown=coverage&src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=pydicom) Report
All modified and coverable lines are covered by tests :white_check_mark:
> Project coverage is 99.85%. Comparing base [(`20993be`)](https://app.codecov.io/gh/pydicom/pynetdicom/commit/20993be78eeaf51053a40a36f0f3eb6304162ba5?dropdown=coverage&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=pydicom) to head [(`ec5cb0c`)](https://app.codecov.io/gh/pydicom/pynetdicom/pull/936?dropdown=coverage&src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=pydicom).
> Report is 5 commits behind head on main.

<details><summary>Additional details and impacted files</summary>


```diff
@@             Coverage Diff             @@
##              main     #936      +/-   ##
===========================================
- Coverage   100.00%   99.85%   -0.15%     
===========================================
  Files           28       28              
  Lines         8703     8706       +3     
===========================================
- Hits          8703     8693      -10     
- Misses           0       13      +13     
```

| [Files](https://app.codecov.io/gh/pydicom/pynetdicom/pull/936?dropdown=coverage&src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=pydicom) | Coverage Δ | |
|---|---|---|
| [pynetdicom/association.py](https://app.codecov.io/gh/pydicom/pynetdicom/pull/936?src=pr&el=tree&filepath=pynetdicom%2Fassociation.py&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=pydicom#diff-cHluZXRkaWNvbS9hc3NvY2lhdGlvbi5weQ==) | `100.00% <100.00%> (ø)` | |
| [pynetdicom/service\_class.py](https://app.codecov.io/gh/pydicom/pynetdicom/pull/936?src=pr&el=tree&filepath=pynetdicom%2Fservice_class.py&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=pydicom#diff-cHluZXRkaWNvbS9zZXJ2aWNlX2NsYXNzLnB5) | `100.00% <100.00%> (ø)` | |

... and [1 file with indirect coverage changes](https://app.codecov.io/gh/pydicom/pynetdicom/pull/936/indirect-changes?src=pr&el=tree-more&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=pydicom)

</details>

Patch:
diff --git a/docs/changelog/v2.1.0.rst b/docs/changelog/v2.1.0.rst
index 49be1dfb4..41f3d65c1 100644
--- a/docs/changelog/v2.1.0.rst
+++ b/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
diff --git a/pynetdicom/association.py b/pynetdicom/association.py
index 65325cef9..b8b366a8d 100644
--- a/pynetdicom/association.py
+++ b/pynetdicom/association.py
@@ -1252,10 +1252,12 @@ class Association(threading.Thread):
 
         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 @@ class Association(threading.Thread):
 
         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 @@ class Association(threading.Thread):
 
         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()
diff --git a/pynetdicom/service_class.py b/pynetdicom/service_class.py
index 71ac885a9..015556173 100644
--- a/pynetdicom/service_class.py
+++ b/pynetdicom/service_class.py
@@ -1364,7 +1364,7 @@ class ServiceClass:
             # 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 @@ class QueryRetrieveServiceClass(ServiceClass):
 
                     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 @@ class QueryRetrieveServiceClass(ServiceClass):
                         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 @@ class QueryRetrieveServiceClass(ServiceClass):
 
                 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)
 


Test patch:
diff --git a/pynetdicom/tests/test_assoc.py b/pynetdicom/tests/test_assoc.py
index 0d2fa22d8..7c061fa5a 100644
--- a/pynetdicom/tests/test_assoc.py
+++ b/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 @@ class TestAssociationSendCFind:
         )
         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 @@ class TestAssociationSendCGet:
 
         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 @@ class TestAssociationSendCMove:
             )
             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."""