From fd9ee86b3f4b7ff1684534c7d75518e7016fe5e1 Mon Sep 17 00:00:00 2001 From: George Vasiliades <1221374+Poseidonas@users.noreply.github.com> Date: Tue, 25 Aug 2026 13:51:19 +0300 Subject: [PATCH 1/2] server: treat a client disconnect as a normal end, not an error Client.disconnect() sends a COTP Disconnect Request, which receive_data() rejected as an unexpected PDU, so an ordinary goodbye from the library's own client was logged as ERROR Error handling client ('127.0.0.1', 58143): Expected COTP DT, got 0x80 COTP_DR and COTP_DC were already defined but never used on the receiving side. A DR is now confirmed with a DC and ends the connection through the path _handle_client already treats as a normal disconnect. Sending the confirmation is best effort, since a client that closes right after the request may already be gone. A peer that goes away before the ISO handshake completes was logged the same way; that is routine (port scans, health checks, a cancelled connect) and is now reported at info level. Measured against the library's own client and a raw socket: a clean disconnect after a request, a clean disconnect without one, a plain TCP close and an abrupt reset all logged an error before, and none do now. --- snap7/server/__init__.py | 26 ++++++++++++++++++++++++ tests/test_server.py | 43 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 69 insertions(+) diff --git a/snap7/server/__init__.py b/snap7/server/__init__.py index 1a652cc7..b1f1714c 100644 --- a/snap7/server/__init__.py +++ b/snap7/server/__init__.py @@ -2606,6 +2606,12 @@ def accept_connection(self) -> bool: logger.debug("ISO connection established") return True + except (ConnectionResetError, ConnectionAbortedError, TimeoutError) as e: + # A peer that goes away before the ISO handshake completes is + # routine - port scans, health checks, a cancelled connect - and + # says nothing about this server. + logger.info(f"Peer left before the ISO connection was established: {e}") + return False except Exception as e: logger.error(f"Error accepting ISO connection: {e}") return False @@ -2638,6 +2644,16 @@ def receive_data(self) -> bytes: pdu_len, pdu_type, eot_num = struct.unpack(">BBB", payload[:3]) + if pdu_type == self.COTP_DR: + # The peer is closing the connection the way ISO 8073 says to; + # confirm it and let the caller treat this as a normal end. + logger.debug("Received COTP DR from client") + try: + self.socket.sendall(self._build_tpkt(self._build_cotp_dc())) + except OSError: + pass # the peer may already be gone + raise ConnectionAbortedError("Client requested disconnect") + if pdu_type != self.COTP_DT: raise S7ConnectionError(f"Expected COTP DT, got {pdu_type:#02x}") @@ -2715,6 +2731,16 @@ def _build_cotp_cc(self) -> bytes: return base_pdu + pdu_size_param + def _build_cotp_dc(self) -> bytes: + """Build COTP Disconnect Confirm.""" + return struct.pack( + ">BBHH", + 5, # PDU length + self.COTP_DC, # PDU type + self.dst_ref, # Destination reference + self.src_ref, # Source reference + ) + def _recv_exact(self, size: int, deadline: float | None = None) -> bytes: """Receive exactly the specified bytes within one absolute deadline.""" if size < 0: diff --git a/tests/test_server.py b/tests/test_server.py index d6a6e4e3..d475c2f5 100644 --- a/tests/test_server.py +++ b/tests/test_server.py @@ -327,6 +327,49 @@ def test_connection_confirm_has_valid_length_and_tpdu_size(self) -> None: assert connection_confirm == bytes.fromhex("09d0000f000100c00109") assert connection_confirm[0] == len(connection_confirm) - 1 + def test_disconnect_confirm_has_valid_length(self) -> None: + client_socket = MagicMock() + connection = ServerISOConnection(client_socket) + connection.dst_ref = 0x000F + connection.src_ref = 0x0001 + + disconnect_confirm = connection._build_cotp_dc() + + assert disconnect_confirm == bytes.fromhex("05c0000f0001") + assert disconnect_confirm[0] == len(disconnect_confirm) - 1 + + def test_a_disconnect_request_ends_the_connection_normally(self) -> None: + # The client sends a COTP DR when it disconnects; treating it as an + # unexpected PDU logs an error for an ordinary goodbye. + client_socket = MagicMock() + connection = ServerISOConnection(client_socket) + connection._recv_exact = MagicMock( + side_effect=[ + b"\x03\x00\x00\x0b", + b"\x06\x80\x00\x00\x01\x00\x00", + ] + ) + + with pytest.raises(ConnectionAbortedError): + connection.receive_data() + + sent = b"".join(call.args[0] for call in client_socket.sendall.call_args_list) + assert sent[5:6] == bytes([connection.COTP_DC]), "the disconnect is confirmed" + + def test_a_disconnect_request_is_confirmed_even_if_the_peer_is_gone(self) -> None: + client_socket = MagicMock() + client_socket.sendall.side_effect = OSError("broken pipe") + connection = ServerISOConnection(client_socket) + connection._recv_exact = MagicMock( + side_effect=[ + b"\x03\x00\x00\x0b", + b"\x06\x80\x00\x00\x01\x00\x00", + ] + ) + + with pytest.raises(ConnectionAbortedError): + connection.receive_data() + def test_partial_frame_timeout_closes_connection(self) -> None: client_socket = MagicMock() client_socket.recv.side_effect = [b"\x03", TimeoutError()] From 67f1d878f44aaf4ffb56efea7483691c2353d294 Mon Sep 17 00:00:00 2001 From: George Vasiliades <1221374+Poseidonas@users.noreply.github.com> Date: Wed, 2 Sep 2026 11:20:04 +0300 Subject: [PATCH 2/2] server: drop the duplicate warning and cover the handshake log levels --- snap7/server/__init__.py | 6 ---- tests/test_server.py | 67 ++++++++++++++++++++++++++++++++++++++-- 2 files changed, 65 insertions(+), 8 deletions(-) diff --git a/snap7/server/__init__.py b/snap7/server/__init__.py index b1f1714c..f1ffdf33 100644 --- a/snap7/server/__init__.py +++ b/snap7/server/__init__.py @@ -625,7 +625,6 @@ def _handle_client(self, client_socket: socket.socket, address: Tuple[str, int]) # Handle ISO connection setup if not connection.accept_connection(): - logger.warning(f"Failed to establish ISO connection with {address}") return logger.info(f"ISO connection established with {address}") @@ -2607,9 +2606,6 @@ def accept_connection(self) -> bool: return True except (ConnectionResetError, ConnectionAbortedError, TimeoutError) as e: - # A peer that goes away before the ISO handshake completes is - # routine - port scans, health checks, a cancelled connect - and - # says nothing about this server. logger.info(f"Peer left before the ISO connection was established: {e}") return False except Exception as e: @@ -2645,8 +2641,6 @@ def receive_data(self) -> bytes: pdu_len, pdu_type, eot_num = struct.unpack(">BBB", payload[:3]) if pdu_type == self.COTP_DR: - # The peer is closing the connection the way ISO 8073 says to; - # confirm it and let the caller treat this as a normal end. logger.debug("Received COTP DR from client") try: self.socket.sendall(self._build_tpkt(self._build_cotp_dc())) diff --git a/tests/test_server.py b/tests/test_server.py index d475c2f5..bf523269 100644 --- a/tests/test_server.py +++ b/tests/test_server.py @@ -339,8 +339,6 @@ def test_disconnect_confirm_has_valid_length(self) -> None: assert disconnect_confirm[0] == len(disconnect_confirm) - 1 def test_a_disconnect_request_ends_the_connection_normally(self) -> None: - # The client sends a COTP DR when it disconnects; treating it as an - # unexpected PDU logs an error for an ordinary goodbye. client_socket = MagicMock() connection = ServerISOConnection(client_socket) connection._recv_exact = MagicMock( @@ -830,6 +828,71 @@ def test_copy_ram_to_rom(self) -> None: self.assertEqual(result, 0) +@pytest.mark.server +class TestHandshakeLogging(unittest.TestCase): + """A peer that leaves before the ISO handshake completes must not raise the log level.""" + + server: Server = None # type: ignore + port: int = 0 + + @classmethod + def setUpClass(cls) -> None: + cls.server = Server() + cls.server.start(0) + assert cls.server.server_socket is not None + cls.port = cls.server.server_socket.getsockname()[1] + + @classmethod + def tearDownClass(cls) -> None: + if cls.server: + cls.server.stop() + cls.server.destroy() + + def _wait_for_record(self, logs, fragment: str, timeout: float = 10.0) -> None: + end = time.monotonic() + timeout + while time.monotonic() < end: + if any(fragment in record.getMessage() for record in logs.records): + return + time.sleep(0.02) + self.fail(f"log containing {fragment!r} did not appear, got: {[r.getMessage() for r in logs.records]}") + + def _assert_no_warnings(self, logs) -> None: + warnings = [r.getMessage() for r in logs.records if r.levelno >= logging.WARNING] + self.assertEqual(warnings, []) + + def test_connect_and_close_logs_no_warning(self) -> None: + with self.assertLogs("snap7.server", level="DEBUG") as logs: + sock = socket.create_connection(("127.0.0.1", self.port), timeout=2) + sock.close() + self._wait_for_record(logs, "Peer left before the ISO connection") + self._assert_no_warnings(logs) + + def test_partial_tpkt_then_close_logs_no_warning(self) -> None: + with self.assertLogs("snap7.server", level="DEBUG") as logs: + sock = socket.create_connection(("127.0.0.1", self.port), timeout=2) + sock.sendall(b"\x03\x00") + sock.close() + self._wait_for_record(logs, "Peer left before the ISO connection") + self._assert_no_warnings(logs) + + def test_malformed_tpkt_still_logs_an_error(self) -> None: + with self.assertLogs("snap7.server", level="DEBUG") as logs: + sock = socket.create_connection(("127.0.0.1", self.port), timeout=2) + sock.sendall(b"\x05\x00\x00\x08garbage!") + self._wait_for_record(logs, "Invalid TPKT version") + sock.close() + self.assertTrue(any(r.levelno == logging.ERROR for r in logs.records)) + self.assertFalse(any(r.levelno == logging.WARNING for r in logs.records)) + + def test_client_connect_and_disconnect_logs_no_warning(self) -> None: + with self.assertLogs("snap7.server", level="DEBUG") as logs: + client = Client() + client.connect(ip, 0, 1, self.port) + client.disconnect() + self._wait_for_record(logs, "disconnected") + self._assert_no_warnings(logs) + + @pytest.mark.server class TestServerErrorScenarios(unittest.TestCase): """Test error handling paths in the server."""