From 6418a2b5451431dcb7669d13dbe99894c47c62ad Mon Sep 17 00:00:00 2001 From: Simon Rose Date: Wed, 7 Oct 2026 10:38:58 +0200 Subject: [PATCH 1/3] Add further logging When logging a protocol error, show the data passed as well. Also, provide better logging during sessions management by the processor. --- server/recceiver/cf/processor.py | 2 ++ server/recceiver/recast.py | 8 ++++---- 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/server/recceiver/cf/processor.py b/server/recceiver/cf/processor.py index 4ae97c75..67ab6f4f 100755 --- a/server/recceiver/cf/processor.py +++ b/server/recceiver/cf/processor.py @@ -409,6 +409,7 @@ def _evict_ioc(self, iocid: str) -> None: Called after a CF push exhausts retries: CF was never written, so in-memory state would diverge from CF until the IOC reconnects. """ + log.info("_evict_ioc: Evicting IOC %s", iocid) # list() snapshots the set; remove_channel mutates it during iteration for ch in list(self._ioc_channels.get(iocid, set())): # NOSONAR self.remove_channel(ch, iocid) @@ -429,6 +430,7 @@ def remove_channel(self, record_name: str, iocid: str) -> None: return self.iocs[iocid].channelcount -= 1 if self.iocs[iocid].channelcount <= 0: + log.info("remove_channel: IOC %s has been emptied of channels, dropped from recceiver.", iocid) if self.iocs[iocid].channelcount < 0: log.error("Channel count negative: %s", iocid) self.iocs.pop(iocid) diff --git a/server/recceiver/recast.py b/server/recceiver/recast.py index abc3cb39..ba0ca797 100644 --- a/server/recceiver/recast.py +++ b/server/recceiver/recast.py @@ -14,7 +14,7 @@ log = logging.getLogger(__name__) -_PROTOCOL_ERROR_MSG = "Protocol error! %s" +_PROTOCOL_ERROR_MSG = "Protocol error! %s (data: %s)" class CastReceiver(stateful.StatefulProtocol): @@ -87,7 +87,7 @@ def recvHeader(self, data): try: header = messages.Header.decode(data) except messages.ProtocolError as exc: - log.exception(_PROTOCOL_ERROR_MSG, exc) + log.exception(_PROTOCOL_ERROR_MSG, exc, data) self.transport.loseConnection() return if header.body_length == 0: @@ -105,7 +105,7 @@ def recvClientGreeting(self, body): try: greeting = messages.ClientGreeting.decode(body) except messages.ProtocolError as exc: - log.exception(_PROTOCOL_ERROR_MSG, exc) + log.exception(_PROTOCOL_ERROR_MSG, exc, body) self.transport.loseConnection() return if greeting.client_type != 0: @@ -122,7 +122,7 @@ def recvPong(self, body): try: pong = messages.Pong.decode(body) except messages.ProtocolError as exc: - log.exception(_PROTOCOL_ERROR_MSG, exc) + log.exception(_PROTOCOL_ERROR_MSG, exc, body) self.transport.loseConnection() return if pong.nonce != self.nonce: From 54c686336f21440a8b87995d8ddadc78ea9f7ab6 Mon Sep 17 00:00:00 2001 From: Simon Rose Date: Wed, 7 Oct 2026 10:41:44 +0200 Subject: [PATCH 2/3] Add log message for greetings --- server/recceiver/recast.py | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/server/recceiver/recast.py b/server/recceiver/recast.py index ba0ca797..a209678f 100644 --- a/server/recceiver/recast.py +++ b/server/recceiver/recast.py @@ -102,6 +102,13 @@ def recvHeader(self, data): # 0x0001 def recvClientGreeting(self, body): + peer = self.transport.getPeer() + log.info( + "Greeting message from %s:%s: body='%s'", + peer.host, + peer.port, + body, + ) try: greeting = messages.ClientGreeting.decode(body) except messages.ProtocolError as exc: @@ -114,7 +121,7 @@ def recvClientGreeting(self, body): return self.version = min(self.version, greeting.version) self.clientKey = greeting.server_key - self.sess = self.factory.addClient(self, self.transport.getPeer()) + self.sess = self.factory.addClient(self, peer) return self.getInitialState() # 0x0002 From 89a78d12e4819c88b9e41a89a2918830d319c384 Mon Sep 17 00:00:00 2001 From: Simon Rose Date: Thu, 8 Oct 2026 10:09:07 +0200 Subject: [PATCH 3/3] Upgrade log severities Several messages that describe exceptional circumstances are being hidden by the debug level log severity. These are being upgraded. General principle is that messages that occur once-per-record should be debug, but once-per-ioc is fine, and anything that is exceptional even on a per-record basis can be info or warning. --- server/recceiver/cf/processor.py | 6 +++--- server/recceiver/processors.py | 4 ++-- server/recceiver/recast.py | 8 ++++---- 3 files changed, 9 insertions(+), 9 deletions(-) diff --git a/server/recceiver/cf/processor.py b/server/recceiver/cf/processor.py index 67ab6f4f..7e498d60 100755 --- a/server/recceiver/cf/processor.py +++ b/server/recceiver/cf/processor.py @@ -269,7 +269,7 @@ def _apply_env_vars( if value is not None: record_infos[record_id].info_properties.append(CFProperty(cf_prop_name, ioc_info.owner, value)) else: - log.debug( + log.info( "EPICS environment var %s not found in IOC: %s", epics_env_var_name, ioc_info, @@ -366,7 +366,7 @@ def _commit_with_thread(self, transaction: interfaces.ITransaction): or self.cf_config.username ) if owner == self.cf_config.username: - log.debug( + log.info( "IOC at %s:%d did not send %s or CF_USERNAME; using service account as owner", host, port, @@ -612,7 +612,7 @@ def _process_new_channels( ) new_properties = new_properties + record_info.info_properties if channel_name in existing_channels: - log.debug("update existing channel %s: exists but with a different iocid from %s", channel_name, iocid) + log.info("update existing channel %s: exists but with a different iocid from %s", channel_name, iocid) self._update_existing_channel_diff_iocid( existing_channels, channel_name, new_properties, channels, record_info_by_name, ioc_info, iocid ) diff --git a/server/recceiver/processors.py b/server/recceiver/processors.py index 29549164..8d2fdf94 100644 --- a/server/recceiver/processors.py +++ b/server/recceiver/processors.py @@ -118,13 +118,13 @@ def config(self, section): def commit(self, trans): def punish(err, processor): if err.check(defer.CancelledError): - log.debug("Cancel processing: %s: %s", processor.name, trans) + log.warning("Cancel processing: %s: %s", processor.name, trans) return err try: self.procs.remove(processor) log.error("Remove processor: %s: %s", processor.name, err) except ValueError: - log.debug("Remove processor: %s: already removed", processor.name) + log.warning("Remove processor: %s: already removed", processor.name) return err defers = [defer.maybeDeferred(P.commit, trans).addErrback(punish, P) for P in self.procs] diff --git a/server/recceiver/recast.py b/server/recceiver/recast.py index a209678f..8f63156c 100644 --- a/server/recceiver/recast.py +++ b/server/recceiver/recast.py @@ -71,7 +71,7 @@ def restartPingTimer(self): def writePing(self): if self.phase == 2: self.transport.loseConnection() - log.debug("pong missed: close connection") + log.warning("pong missed: close connection") else: self.restartPingTimer() self.phase = 2 @@ -91,7 +91,7 @@ def recvHeader(self, data): self.transport.loseConnection() return if header.body_length == 0: - log.debug("Ignoring empty message %#06x", header.msg_id) + log.warning("Ignoring empty message %#06x", header.msg_id) return self.getInitialState() self.msgid = header.msg_id fn, minlen = self.rxfn[self.msgid] @@ -334,12 +334,12 @@ def abort(err): # between transactions. Only flush after Add or Del or Done message received. def flush_safely(self): if self._flush_deadline and self._flush_deadline <= time.time(): - log.debug("flush_safely: timeout elapsed for %s", self.ep) + log.warning("flush_safely: timeout elapsed for %s", self.ep) self.flush() elif self.trlimit and self.trlimit <= ( len(self.transaction.records_to_add) + len(self.transaction.records_to_delete) ): - log.debug("flush_safely: trlimit %d reached for %s", self.trlimit, self.ep) + log.warning("flush_safely: trlimit %d reached for %s", self.trlimit, self.ep) self.flush() def mark_dirty(self):