Skip to content

Add even more logging #183

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
simon-ess merged 3 commits into from
Oct 9, 2026
Merged

Add even more logging #183

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
6418a2b
Add further logging
simon-ess Oct 7, 2026
54c6863
Add log message for greetings
simon-ess Oct 7, 2026
89a78d1
Upgrade log severities
simon-ess Oct 8, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 5 additions & 3 deletions server/recceiver/cf/processor.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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)
Expand All @@ -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)
Expand Down Expand Up @@ -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
)
Expand Down
4 changes: 2 additions & 2 deletions server/recceiver/processors.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand Down
25 changes: 16 additions & 9 deletions server/recceiver/recast.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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):
Expand Down Expand Up @@ -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
Expand All @@ -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]
Expand All @@ -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:
Expand All @@ -114,15 +121,15 @@ 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
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:
Expand Down Expand Up @@ -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):
Expand Down
Loading