From a9fc21e1e734f2c1fe80c4e2a16a4013bb242c08 Mon Sep 17 00:00:00 2001
From: Sky Brewer <sky.brewer@ess.eu>
Date: Wed, 3 Apr 2024 11:27:21 +0200
Subject: [PATCH] Add some extra logs to recceiver

---
 server/recceiver/announce.py    |  3 ++-
 server/recceiver/application.py |  8 +++++---
 server/recceiver/cfstore.py     | 11 +++++++----
 server/recceiver/dbstore.py     |  8 ++++++++
 4 files changed, 22 insertions(+), 8 deletions(-)

diff --git a/server/recceiver/announce.py b/server/recceiver/announce.py
index f315e46..a6af907 100644
--- a/server/recceiver/announce.py
+++ b/server/recceiver/announce.py
@@ -33,13 +33,14 @@ def __init__(self, tcpport, key=0,
             raise RuntimeError('Announce list is empty at start time...')
 
     def startProtocol(self):
-        _log.info('setup Announcer')
+        _log.info('Setup Announcer')
         self.D = self.reactor.callLater(0, self.sendOne)
         # we won't process any receieved traffic, so no reason to wake
         # up for it...
         self.transport.pauseProducing()
 
     def stopProtocol(self):
+        _log.info('Stop Announcer')
         self.D.cancel()
         del self.D
 
diff --git a/server/recceiver/application.py b/server/recceiver/application.py
index 50da82b..9611054 100644
--- a/server/recceiver/application.py
+++ b/server/recceiver/application.py
@@ -16,6 +16,8 @@
 from .announce import Announcer
 from .processors import ProcessorController
 
+_log = logging.getLogger(__name__)
+
 class Log2Twisted(logging.StreamHandler):
     """Print logging module stream to the twisted log
     """
@@ -65,7 +67,7 @@ def __init__(self, config):
 
     def privilegedStartService(self):
 
-        print('Starting')
+        _log.info('Starting RecService')
 
         # Start TCP server on random port
         self.tcpFactory = CastFactory()
@@ -87,7 +89,7 @@ def privilegedStartService(self):
 
         # Find out which port is in use
         addr = self.tcp.getHost()
-        print('listening on',addr)
+        _log.info('RecService listening on ', addr)
 
         self.key = random.randint(0,0xffffffff)
 
@@ -138,7 +140,7 @@ def makeService(self, opts):
                 lvl = logging.WARN
         else:
             if not isinstance(lvl, (int, )):
-                print("Invalid loglevel", lvlname)
+                _log.info("Invalid loglevel", lvlname)
                 lvl = logging.WARN
 
         fmt = conf.get('logformat', "%(levelname)s:%(name)s %(message)s")
diff --git a/server/recceiver/cfstore.py b/server/recceiver/cfstore.py
index 94b5ef1..7e05614 100755
--- a/server/recceiver/cfstore.py
+++ b/server/recceiver/cfstore.py
@@ -111,6 +111,7 @@ def _startServiceWithLock(self):
                     self.clean_service()
 
     def stopService(self):
+        _log.info('CF_STOP')
         service.Service.stopService(self)
         return self.lock.run(self._stopServiceWithLock)
 
@@ -118,7 +119,7 @@ def _stopServiceWithLock(self):
         # Set channels to inactive and close connection to client
         if self.conf.getboolean('cleanOnStop', True):
             self.clean_service()
-        _log.info("CF_STOP")
+        _log.info("CF_STOP with lock")
 
     # @defer.inlineCallbacks # Twisted v16 does not support cancellation!
     def commit(self, transaction_record):
@@ -321,6 +322,8 @@ def dict_to_file(dict, iocs, conf):
 
 
 def __updateCF__(proc, pvInfoByName, delrec, hostName, iocName, iocid, owner, iocTime):
+    _log.info("CF Update IOC: %s", iocid)
+
     # Consider making this function a class methed then 'proc' simply becomes 'self'
     client = proc.client
     channels_dict = proc.channel_dict
@@ -512,7 +515,7 @@ def __updateCF__(proc, pvInfoByName, delrec, hostName, iocName, iocid, owner, io
                                     u'owner': owner,
                                     u'properties': alProps})
                         _log.debug("Add new alias: %s", channels[-1])
-    _log.info("Total channels to update: %s", len(channels))
+    _log.info("Total channels to update: %s %s", len(channels), iocName)
     if len(channels) != 0:
         client.set(channels=channels)
     else:
@@ -546,7 +549,7 @@ def prepareFindArgs(conf, args):
 
 
 def poll(update, proc, pvInfoByName, delrec, hostName, iocName, iocid, owner, iocTime):
-    _log.debug("Polling begins...")
+    _log.info("Polling %s begins...", iocName)
     sleep = 1
     success = False
     while not success:
@@ -560,4 +563,4 @@ def poll(update, proc, pvInfoByName, delrec, hostName, iocName, iocid, owner, io
             #_log.debug(str(channels_dict))
             time.sleep(min(60, sleep))
             sleep *= 1.5
-    _log.debug("Polling complete")
+    _log.info("Polling %s complete", iocName)
diff --git a/server/recceiver/dbstore.py b/server/recceiver/dbstore.py
index cecf17c..189b7f6 100644
--- a/server/recceiver/dbstore.py
+++ b/server/recceiver/dbstore.py
@@ -1,6 +1,7 @@
 # -*- coding: utf-8 -*-
 
 import itertools
+import logging
 
 from zope.interface import implementer
 
@@ -10,6 +11,8 @@
 
 from . import interfaces
 
+_log = logging.getLogger(__name__)
+
 __all__  = ['DBProcessor']
 
 @implementer(interfaces.IProcessor)
@@ -37,6 +40,7 @@ def waitFor(self, D):
         return D
 
     def startService(self):
+        _log.info("Start DBService")
         service.Service.startService(self)
 
         # map of source id# to server table id keys
@@ -64,6 +68,8 @@ def startService(self):
         self.waitFor(self.pool.runInteraction(self.cleanupDB))
 
     def stopService(self):
+        _log.info("Stop DBService")
+
         service.Service.stopService(self)
 
         self.waitFor(self.pool.runInteraction(self.cleanupDB))
@@ -73,6 +79,8 @@ def stopService(self):
         return defer.DeferredList(list(self.Ds), consumeErrors=True)
 
     def cleanupDB(self, cur):
+        _log.info("Cleanup DBService")
+
         assert self.mykey != 0
         cur.execute('PRAGMA foreign_keys = ON;')
         cur.execute('DELETE FROM %s WHERE owner=?' % self.tserver,