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)
more_events
Jose M. Guisado 2022-06-06 14:45:41 +02:00
parent 1ab981a539
commit 30fdcceea3
9 changed files with 93 additions and 27 deletions

View File

@ -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"

View File

@ -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()

View File

@ -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):

View File

@ -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)

View File

@ -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))

View File

@ -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

View File

@ -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:

View File

@ -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():

View File

@ -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