src: improve logging

Adds new logging handler redirecting messages to the log file
located in the Samba shared directory (applies to live mode
clients, i.e: ogLive)

Parses log level configuration from ogclient.json. See:

{
	"opengnsys": {
		...
                "log": "INFO",
		...
	}
	...
}

Adds --debug option to set root logger level to DEBUG when starting
ogClient. Overrides log level from config file.

In addition:

- Replaces any occurence of print with a corresponding logging function.
- Unsets log level for handlers, use root logger level instead.
- Default level for root logger is INFO.
- Replaces level from response log messages to debug (ogRest)

9 files changed, 93 insertions, 27 deletions

diff --git a/cfg/ogclient.json b/cfg/ogclient.json
index 1a43d1b..b1f1f43 100644
--- a/cfg/ogclient.json
+++ b/cfg/ogclient.json
@@ -2,7 +2,7 @@
 	"opengnsys": {
 		"ip": "127.0.0.1",
 		"port": 8889,
-		"log": "DEBUG",
+		"log": "INFO",
 		"mode": "live",
 		"url": "https://127.0.0.1/opengnsys/varios/menubrowser.php",
 		"url_log": "http://localhost/cgi-bin/httpd-log.sh"
diff --git a/ogclient b/ogclient
index be7a7f1..8798ed6 100755
--- a/ogclient
+++ b/ogclient
@@ -46,6 +46,9 @@ def create_parser():
 
 	parser.add_argument('-c', '--config', default="",
 			    help='ogClient JSON config file path')
+	parser.add_argument('--debug', default=False,
+			    action='store_true',
+			    help='enables debug log level')
 
 	return parser
 
@@ -73,12 +76,17 @@ def main():
 
 	MODE = CONFIG['opengnsys']['mode']
 	URL = CONFIG['opengnsys']['url']
+	LOGLEVEL = CONFIG['opengnsys']['log']
+
 	if MODE == 'live':
 		proc = subprocess.Popen(["browser", "-qws", URL])
 	if MODE != 'windows':
 		signal.signal(SIGPIPE, SIG_DFL)
 
-	configure_logging(MODE)
+	configure_logging(MODE, LOGLEVEL)
+
+	if args.debug:
+		logging.getLogger().setLevel('DEBUG')
 
 	client = ogClient(config=CONFIG)
 	client.connect()
diff --git a/src/live/ogOperations.py b/src/live/ogOperations.py
index efdc813..5533312 100644
--- a/src/live/ogOperations.py
+++ b/src/live/ogOperations.py
@@ -6,6 +6,7 @@
 # Free Software Foundation; either version 3 of the License, or
 # (at your option) any later version.
 
+import logging
 import os
 import subprocess
 
@@ -115,6 +116,7 @@ class OgLiveOperations:
         return parsed
 
     def poweroff(self):
+        logging.info('Powering off client')
         if os.path.exists('/scripts/oginit'):
             cmd = f'source {ogClient.OG_PATH}etc/preinit/loadenviron.sh; ' \
                   f'{ogClient.OG_PATH}scripts/poweroff'
@@ -123,6 +125,7 @@ class OgLiveOperations:
             subprocess.call(['/sbin/poweroff'])
 
     def reboot(self):
+        logging.info('Rebooting client')
         if os.path.exists('/scripts/oginit'):
             cmd = f'source {ogClient.OG_PATH}etc/preinit/loadenviron.sh; ' \
                   f'{ogClient.OG_PATH}scripts/reboot'
@@ -143,8 +146,14 @@ class OgLiveOperations:
                                executable=OG_SHELL)
             (output, error) = ogRest.proc.communicate()
         except:
+            logging.error('Exception when running "shell run" subprocess')
             raise ValueError('Error: Incorrect command value')
 
+        if ogRest.proc.returncode != 0:
+            logging.warn('Non zero exit code when running: %s', ' '.join(cmds))
+        else:
+            logging.info('Shell run command OK')
+
         self.refresh(ogRest)
 
         return output.decode('utf-8')
@@ -161,8 +170,10 @@ class OgLiveOperations:
                                executable=OG_SHELL)
             (output, error) = ogRest.proc.communicate()
         except:
+            logging.error('Exception when running session subprocess')
             raise ValueError('Error: Incorrect command value')
 
+        logging.info('Starting OS at disk %s partition %s', disk, partition)
         return output.decode('utf-8')
 
     def software(self, request, path, ogRest):
@@ -181,6 +192,7 @@ class OgLiveOperations:
                                executable=OG_SHELL)
             (output, error) = ogRest.proc.communicate()
         except:
+            logging.error('Exception when running software inventory subprocess')
             raise ValueError('Error: Incorrect command value')
 
         self._restartBrowser(self._url)
@@ -188,6 +200,8 @@ class OgLiveOperations:
         software = ''
         with open(path, 'r') as f:
             software = f.read()
+
+        logging.info('Software inventory command OK')
         return software
 
     def hardware(self, path, ogRest):
@@ -201,10 +215,12 @@ class OgLiveOperations:
                                executable=OG_SHELL)
             (output, error) = ogRest.proc.communicate()
         except:
+            logging.error('Exception when running hardware inventory subprocess')
             raise ValueError('Error: Incorrect command value')
 
         self._restartBrowser(self._url)
 
+        logging.info('Hardware inventory command OK')
         return output.decode('utf-8')
 
     def setup(self, request, ogRest):
@@ -231,8 +247,10 @@ class OgLiveOperations:
                                executable=OG_SHELL)
             (output, error) = ogRest.proc.communicate()
         except:
+            logging.error('Exception when running setup subprocess')
             raise ValueError('Error: Incorrect command value')
 
+        logging.info('Setup command OK')
         result = self.refresh(ogRest)
 
         return result
@@ -259,10 +277,12 @@ class OgLiveOperations:
             if (ogRest.proc.returncode):
                 raise Exception
         except:
+            logging.error('Exception when running image restore subprocess')
             raise ValueError('Error: Incorrect command value')
 
         self.refresh(ogRest)
 
+        logging.info('Image restore command OK')
         return output.decode('utf-8')
 
     def image_create(self, path, request, ogRest):
@@ -284,6 +304,7 @@ class OgLiveOperations:
                                executable=OG_SHELL)
             (output, error) = ogRest.proc.communicate()
         except:
+            logging.error('Exception when running software inventory subprocess')
             raise ValueError('Error: Incorrect command value')
 
         if ogRest.terminated:
@@ -296,9 +317,11 @@ class OgLiveOperations:
                                executable=OG_SHELL)
             ogRest.proc.communicate()
         except:
+            logging.error('Exception when running "image create" subprocess')
             raise ValueError('Error: Incorrect command value')
 
         if ogRest.proc.returncode != 0:
+            logging.warn('Image creation failed')
             raise ValueError('Error: Image creation failed')
 
         with open('/tmp/image.info') as file_info:
@@ -316,6 +339,7 @@ class OgLiveOperations:
 
         self._restartBrowser(self._url)
 
+        logging.info('Image creation command OK')
         return image_info
 
     def refresh(self, ogRest):
@@ -332,7 +356,7 @@ class OgLiveOperations:
         }
 
         for num_disk, disk in enumerate(get_disks(), start=1):
-            print(disk)
+            logging.debug('refresh: processing %s', disk)
             part_setup = {}
             try:
                 cxt = fdisk.Context(device=f'/dev/{disk}')
@@ -352,6 +376,7 @@ class OgLiveOperations:
         generate_cache_txt()
         self._restartBrowser(self._url)
 
+        logging.info('Sending response to refresh request')
         return parsed
 
     def probe(self, ogRest):
diff --git a/src/log.py b/src/log.py
index 9d379eb..bf00c71 100644
--- a/src/log.py
+++ b/src/log.py
@@ -1,5 +1,8 @@
 import logging
 import logging.config
+import os
+
+from src.utils.net import getifaddr
 
 DEFAULT_LOGGING_LINUX = {
     'version': 1,
@@ -15,25 +18,34 @@ DEFAULT_LOGGING_LINUX = {
             'format': '[{levelname}] - {message}',
             'style': '{',
         },
+        'formatter.syslogtime': {
+            '()': 'logging.Formatter',
+            'datefmt': '%Y-%m-%d %H:%M:%S',
+            'format': '({asctime}) ogClient: [{levelname}] - {message}',
+            'style': '{',
+        },
     },
     'handlers': {
         'console': {
-            'level': 'INFO',
             'class': 'logging.StreamHandler',
             'formatter': 'formatter.console',
             'stream': 'ext://sys.stdout',
         },
         'syslog': {
-            'level': 'DEBUG',
             'class': 'logging.handlers.SysLogHandler',
             'formatter': 'formatter.syslog',
             'address': '/dev/log',
         },
+        'samba': {
+            'class': 'logging.FileHandler',
+            'formatter': 'formatter.syslogtime',
+            'filename': f'/opt/opengnsys/log/{getifaddr(os.getenv("DEVICE"))}.log',
+        },
     },
     'loggers': {
         '': {
             'handlers': ['syslog', 'console'],
-            'level': 'DEBUG',
+            'level': 'INFO',
         },
     }
 }
@@ -64,9 +76,23 @@ DEFAULT_LOGGING_WIN = {
     }
 }
 
-def configure_logging(mode):
+def configure_logging(mode, level):
+    """
+    Receives a ogClient operating mode.
+
+    Configures the default logger according to the operating mode.
+
+    For example, in the case of running live mode it will activate
+    logging to the expected samba shared log file ({ip}.txt.log).
+    """
     if mode == 'windows':
-        DEFAULT_LOGGING = DEFAULT_LOGGING_WIN
+        logconfig = DEFAULT_LOGGING_WIN
     else:
-        DEFAULT_LOGGING = DEFAULT_LOGGING_LINUX
-    logging.config.dictConfig(DEFAULT_LOGGING)
+        logconfig = DEFAULT_LOGGING_LINUX
+
+    if mode == 'live':
+        logconfig['loggers']['']['handlers'].append('samba')
+
+    logconfig['loggers']['']['level'] = level
+
+    logging.config.dictConfig(logconfig)
diff --git a/src/ogClient.py b/src/ogClient.py
index 67e0d51..04b6d01 100644
--- a/src/ogClient.py
+++ b/src/ogClient.py
@@ -11,6 +11,7 @@ import select
 import socket
 import time
 import email
+import logging
 from io import StringIO
 
 from src.restRequest import *
@@ -30,6 +31,7 @@ class ogClient:
 
 		self.mode = self.CONFIG['opengnsys']['mode']
 		if self.mode not in {'virtual', 'live', 'linux', 'windows'}:
+			logging.critical('Invalid ogClient mode')
 			raise ValueError('Mode not supported.')
 		if self.mode in {'linux', 'windows'}:
 			self.event_sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
@@ -58,19 +60,20 @@ class ogClient:
 	def send_event_hint(self, message):
 		try:
 			event, action, user = message.split(" ")
-			logging.warning("%s, %s, %s", event, action, user)
+			logging.debug('Sending event: %s, %s, %s', event, action, user)
 		except:
-			logging.warning("Error parsing session datagram")
+			logging.warning('Error parsing session datagram')
 			return
 
 		if (event != "session" or
 		    action not in ['start', 'stop'] or
 		    not user):
-			logging.warning("Invalid value in session datagram: %s", message)
+			logging.warning('Invalid value in session datagram: %s', message)
 
 		payload = jsonBody({'event': event, 'action': action, 'user': user})
 		response = restResponse(ogResponses.EARLY_HINTS, payload)
 		self.send(response.get())
+		logging.debug('Sending event OK')
 
 	def cleanup(self):
 		self.data = ""
@@ -79,7 +82,7 @@ class ogClient:
 		self.trailer = False
 
 	def connect(self):
-		print('connecting...')
+		logging.debug('Connecting...')
 		self.sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
 		self.sock.setblocking(0)
 		self.sock.setsockopt(socket.SOL_SOCKET, socket.SO_KEEPALIVE, 1)
@@ -107,11 +110,11 @@ class ogClient:
 			self.sock.connect((self.ip, self.port))
 		except socket.error as err:
 			if err.errno == errno.EISCONN:
-				print('connected')
+				logging.debug('Connected')
 				self.state = State.RECEIVING
 			else:
 				time.sleep(1)
-				print('connection refused, retrying...')
+				logging.warning('Connection refused, retrying...')
 				self.state = State.CONNECTING
 				self.sock.close()
 				self.connect()
@@ -121,7 +124,7 @@ class ogClient:
 			data = self.sock.recv(1024).decode('utf-8')
 		except socket.error as err:
 			data = ''
-			print('failed to received ' + str(err))
+			logging.warning('Receive failed: %s', str(err))
 
 		if len(data) == 0:
 			self.sock.close()
@@ -185,4 +188,4 @@ class ogClient:
 				message = event_sock.recv(4096).decode('utf-8').rstrip()
 				self.send_event_hint(message)
 			else:
-				print('wrong state, not ever happen!' + str(state))
+				logging.critical('Invalid state: %s', str(state))
diff --git a/src/ogRest.py b/src/ogRest.py
index 0207af0..8e54612 100644
--- a/src/ogRest.py
+++ b/src/ogRest.py
@@ -60,7 +60,7 @@ class restResponse():
 			return self.msg
 
 		if response in {ogResponses.OK, ogResponses.IN_PROGRESS}:
-			LOGGER.info(self.msg[:ogRest.LOG_LENGTH])
+			LOGGER.debug(self.msg[:ogRest.LOG_LENGTH])
 		else:
 			LOGGER.warn(self.msg[:ogRest.LOG_LENGTH])
 
@@ -281,7 +281,7 @@ class ogRest():
 		method = request.get_method()
 		URI = request.get_uri()
 
-		LOGGER.debug('%s%s', method, URI[:ogRest.LOG_LENGTH])
+		LOGGER.debug('Incoming request: %s%s', method, URI[:ogRest.LOG_LENGTH])
 
 		if (not "stop" in URI and
 		    not "reboot" in URI and
diff --git a/src/restRequest.py b/src/restRequest.py
index 9a9c624..61d64c6 100644
--- a/src/restRequest.py
+++ b/src/restRequest.py
@@ -7,8 +7,10 @@
 # (at your option) any later version.
 
 import email
-from io import StringIO
 import json
+import logging
+
+from io import StringIO
 
 class restRequest:
 	def __init__(self):
@@ -57,7 +59,7 @@ class restRequest:
 			try:
 				json_param = json.loads(body)
 			except ValueError as e:
-				print ("Error: Json message incomplete")
+				logging.error("JSON message incomplete")
 				return
 
 			if "run" in json_param:
diff --git a/src/utils/cache.py b/src/utils/cache.py
index 150a5df..3bd4053 100644
--- a/src/utils/cache.py
+++ b/src/utils/cache.py
@@ -6,6 +6,7 @@
 # Free Software Foundation; either version 3 of the License, or
 # (at your option) any later version.
 
+import logging
 import os
 
 from src.utils.fs import mount_mkdir, umount
@@ -45,7 +46,7 @@ def write_cache_txt(content):
     """
     client_ip = getifaddr(os.getenv('DEVICE'))
     with open(OGCLIENT_LOG_CACHE.format(ip=client_ip), 'w') as f:
-        print("About to write")
+        logging.debug('Writing cache contents to %s.cache.txt', client_ip)
         f.write(content)
 
 def generate_cache_txt():
diff --git a/src/virtual/poweroffd.py b/src/virtual/poweroffd.py
index 63d08e1..83adee1 100644
--- a/src/virtual/poweroffd.py
+++ b/src/virtual/poweroffd.py
@@ -6,6 +6,7 @@
 # Free Software Foundation; either version 3 of the License, or
 # (at your option) any later version.
 
+import logging
 
 from src.virtual.qmp import QEMUMonitorProtocol
 from src.virtual.qmp import QMPCapabilitiesError, QMPConnectError
@@ -26,10 +27,10 @@ def init(host=QMP_DEFAULT_HOST, port=QMP_DEFAULT_PORT):
     try:
         qmpconn.connect()
     except ConnectionRefusedError:
-        print("Critical err: Connection refused")
+        logging.critical('poweroffd: Connection refused')
         return None
     except QMPCapabilitiesError as e:
-        print("Error negotiating capabilities")
+        logging.critical('poweroffd: Error negotiating capabilities')
         return None
     return qmpconn
 
@@ -41,11 +42,11 @@ def run(qmpconn):
         try:
             qmp_ev = qmpconn.pull_event(wait=True)
         except QMPConnectError as e:
-            print("Error trying to pull an event")
+            logging.critical('Error trying to pull an event')
             ret = -1
             break
         if is_shutdown_event(qmp_ev):
-            print("Detected guest shutdown, let's go")
+            logging.info('Detected guest shutdown, powering off')
             ret = 0
             break