diff --git a/server/recceiver/cf/processor.py b/server/recceiver/cf/processor.py index 4ae97c75..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, @@ -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) @@ -610,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 abc3cb39..8f63156c 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): @@ -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 @@ -87,11 +87,11 @@ 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: - 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] @@ -102,10 +102,17 @@ 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: - log.exception(_PROTOCOL_ERROR_MSG, exc) + log.exception(_PROTOCOL_ERROR_MSG, exc, body) self.transport.loseConnection() return if greeting.client_type != 0: @@ -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 @@ -122,7 +129,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: @@ -327,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):