Implement node logging into Zookeeper

Adds the ability to send node daemon logs to Zookeeper to facilitate a
command like "pvc node log", similar to "pvc vm log". Each node stores
its logs in a separate tree under "/logs" which can then be combined or
queried. By default, set by config, only 2000 lines are kept.
This commit is contained in:
Joshua Boniface 2021-07-18 17:03:57 -04:00
parent cd1db3d587
commit 323c7c41ae
5 changed files with 76 additions and 7 deletions

View File

@ -1,6 +1,6 @@
#!/usr/bin/env python3 #!/usr/bin/env python3
# log.py - Output (stdout + logfile) functions # log.py - PVC daemon logger functions
# Part of the Parallel Virtual Cluster (PVC) system # Part of the Parallel Virtual Cluster (PVC) system
# #
# Copyright (C) 2018-2021 Joshua M. Boniface <joshua@boniface.me> # Copyright (C) 2018-2021 Joshua M. Boniface <joshua@boniface.me>
@ -19,7 +19,12 @@
# #
############################################################################### ###############################################################################
import datetime from collections import deque
from threading import Thread
from queue import Queue
from datetime import datetime
from daemon_lib.zkhandler import ZKHandler
class Logger(object): class Logger(object):
@ -77,6 +82,10 @@ class Logger(object):
self.last_colour = '' self.last_colour = ''
self.last_prompt = '' self.last_prompt = ''
if self.config['zookeeper_logging']:
self.zookeeper_logger = ZookeeperLogger(config)
self.zookeeper_logger.start()
# Provide a hup function to close and reopen the writer # Provide a hup function to close and reopen the writer
def hup(self): def hup(self):
self.writer.close() self.writer.close()
@ -87,7 +96,7 @@ class Logger(object):
# Get the date # Get the date
if self.config['log_dates']: if self.config['log_dates']:
date = '{} - '.format(datetime.datetime.now().strftime('%Y/%m/%d %H:%M:%S.%f')) date = '{} - '.format(datetime.now().strftime('%Y/%m/%d %H:%M:%S.%f'))
else: else:
date = '' date = ''
@ -123,6 +132,53 @@ class Logger(object):
if self.config['file_logging']: if self.config['file_logging']:
self.writer.write(message + '\n') self.writer.write(message + '\n')
# Log to Zookeeper
if self.config['zookeeper_logging']:
self.zookeeper_logger.queue.put(message)
# Set last message variables # Set last message variables
self.last_colour = colour self.last_colour = colour
self.last_prompt = prompt self.last_prompt = prompt
class ZookeeperLogger(Thread):
"""
Defines a threaded writer for Zookeeper locks. Threading prevents the blocking of other
daemon events while the records are written. They will be eventually-consistent
"""
def __init__(self, config):
self.config = config
self.node = self.config['node']
self.max_lines = self.config['node_log_lines']
self.queue = Queue()
self.zkhandler = None
self.start_zkhandler()
self.zkhandler.write([(('logs', self.node), '')])
Thread.__init__(self, args=(), kwargs=None)
def start_zkhandler(self):
# We must open our own dedicated Zookeeper instance because we can't guarantee one already exists when this starts
if self.zkhandler is not None:
try:
self.zkhandler.disconnect()
except Exception:
pass
self.zkhandler = ZKHandler(self.config, logger=None)
self.zkhandler.connect(persistent=True)
def run(self):
while True:
message = self.queue.get()
self.write_log(message)
def write_log(self, message):
# Log to Zookeeper
with self.zkhandler.writelock(('logs.messages', self.node)):
logs = deque(self.zkhandler.read(('logs.messages', self.node)).split('\n'), self.max_lines)
if not self.config['log_dates']:
# We want to log dates here, even if the log_dates config is not set
date = '{} - '.format(datetime.now().strftime('%Y/%m/%d %H:%M:%S.%f'))
else:
date = ''
logs.append(f'{date}{message}')
self.zkhandler.write([(('logs.messages', self.node), '\n'.join(logs))])

View File

@ -0,0 +1 @@
{"version": "4", "root": "", "base": {"root": "", "schema": "/schema", "schema.version": "/schema/version", "config": "/config", "config.maintenance": "/config/maintenance", "config.primary_node": "/config/primary_node", "config.primary_node.sync_lock": "/config/primary_node/sync_lock", "config.upstream_ip": "/config/upstream_ip", "config.migration_target_selector": "/config/migration_target_selector", "cmd": "/cmd", "cmd.node": "/cmd/nodes", "cmd.domain": "/cmd/domains", "cmd.ceph": "/cmd/ceph", "logs": "/logs", "node": "/nodes", "domain": "/domains", "network": "/networks", "storage": "/ceph", "storage.util": "/ceph/util", "osd": "/ceph/osds", "pool": "/ceph/pools", "volume": "/ceph/volumes", "snapshot": "/ceph/snapshots"}, "logs": {"node": "", "messages": "/messages"}, "node": {"name": "", "keepalive": "/keepalive", "mode": "/daemonmode", "data.active_schema": "/activeschema", "data.latest_schema": "/latestschema", "data.static": "/staticdata", "data.pvc_version": "/pvcversion", "running_domains": "/runningdomains", "count.provisioned_domains": "/domainscount", "count.networks": "/networkscount", "state.daemon": "/daemonstate", "state.router": "/routerstate", "state.domain": "/domainstate", "cpu.load": "/cpuload", "vcpu.allocated": "/vcpualloc", "memory.total": "/memtotal", "memory.used": "/memused", "memory.free": "/memfree", "memory.allocated": "/memalloc", "memory.provisioned": "/memprov", "ipmi.hostname": "/ipmihostname", "ipmi.username": "/ipmiusername", "ipmi.password": "/ipmipassword", "sriov": "/sriov", "sriov.pf": "/sriov/pf", "sriov.vf": "/sriov/vf"}, "sriov_pf": {"phy": "", "mtu": "/mtu", "vfcount": "/vfcount"}, "sriov_vf": {"phy": "", "pf": "/pf", "mtu": "/mtu", "mac": "/mac", "phy_mac": "/phy_mac", "config": "/config", "config.vlan_id": "/config/vlan_id", "config.vlan_qos": "/config/vlan_qos", "config.tx_rate_min": "/config/tx_rate_min", "config.tx_rate_max": "/config/tx_rate_max", "config.spoof_check": "/config/spoof_check", "config.link_state": "/config/link_state", "config.trust": "/config/trust", "config.query_rss": "/config/query_rss", "pci": "/pci", "pci.domain": "/pci/domain", "pci.bus": "/pci/bus", "pci.slot": "/pci/slot", "pci.function": "/pci/function", "used": "/used", "used_by": "/used_by"}, "domain": {"name": "", "xml": "/xml", "state": "/state", "profile": "/profile", "stats": "/stats", "node": "/node", "last_node": "/lastnode", "failed_reason": "/failedreason", "storage.volumes": "/rbdlist", "console.log": "/consolelog", "console.vnc": "/vnc", "meta.autostart": "/node_autostart", "meta.migrate_method": "/migration_method", "meta.node_selector": "/node_selector", "meta.node_limit": "/node_limit", "meta.tags": "/tags", "migrate.sync_lock": "/migrate_sync_lock"}, "tag": {"name": "", "type": "/type", "protected": "/protected"}, "network": {"vni": "", "type": "/nettype", "rule": "/firewall_rules", "rule.in": "/firewall_rules/in", "rule.out": "/firewall_rules/out", "nameservers": "/name_servers", "domain": "/domain", "reservation": "/dhcp4_reservations", "lease": "/dhcp4_leases", "ip4.gateway": "/ip4_gateway", "ip4.network": "/ip4_network", "ip4.dhcp": "/dhcp4_flag", "ip4.dhcp_start": "/dhcp4_start", "ip4.dhcp_end": "/dhcp4_end", "ip6.gateway": "/ip6_gateway", "ip6.network": "/ip6_network", "ip6.dhcp": "/dhcp6_flag"}, "reservation": {"mac": "", "ip": "/ipaddr", "hostname": "/hostname"}, "lease": {"mac": "", "ip": "/ipaddr", "hostname": "/hostname", "expiry": "/expiry", "client_id": "/clientid"}, "rule": {"description": "", "rule": "/rule", "order": "/order"}, "osd": {"id": "", "node": "/node", "device": "/device", "stats": "/stats"}, "pool": {"name": "", "pgs": "/pgs", "stats": "/stats"}, "volume": {"name": "", "stats": "/stats"}, "snapshot": {"name": "", "stats": "/stats"}}

View File

@ -466,7 +466,7 @@ class ZKHandler(object):
# #
class ZKSchema(object): class ZKSchema(object):
# Current version # Current version
_version = 3 _version = 4
# Root for doing nested keys # Root for doing nested keys
_schema_root = '' _schema_root = ''
@ -490,6 +490,7 @@ class ZKSchema(object):
'cmd.node': f'{_schema_root}/cmd/nodes', 'cmd.node': f'{_schema_root}/cmd/nodes',
'cmd.domain': f'{_schema_root}/cmd/domains', 'cmd.domain': f'{_schema_root}/cmd/domains',
'cmd.ceph': f'{_schema_root}/cmd/ceph', 'cmd.ceph': f'{_schema_root}/cmd/ceph',
'logs': '/logs',
'node': f'{_schema_root}/nodes', 'node': f'{_schema_root}/nodes',
'domain': f'{_schema_root}/domains', 'domain': f'{_schema_root}/domains',
'network': f'{_schema_root}/networks', 'network': f'{_schema_root}/networks',
@ -500,6 +501,11 @@ class ZKSchema(object):
'volume': f'{_schema_root}/ceph/volumes', 'volume': f'{_schema_root}/ceph/volumes',
'snapshot': f'{_schema_root}/ceph/snapshots', 'snapshot': f'{_schema_root}/ceph/snapshots',
}, },
# The schema of an individual logs entry (/logs/{node_name})
'logs': {
'node': '', # The root key
'messages': '/messages',
},
# The schema of an individual node entry (/nodes/{node_name}) # The schema of an individual node entry (/nodes/{node_name})
'node': { 'node': {
'name': '', # The root key 'name': '', # The root key
@ -771,7 +777,7 @@ class ZKSchema(object):
logger.out(f'Key not found: {self.path(kpath)}', state='w') logger.out(f'Key not found: {self.path(kpath)}', state='w')
result = False result = False
for elem in ['node', 'domain', 'network', 'osd', 'pool']: for elem in ['logs', 'node', 'domain', 'network', 'osd', 'pool']:
# First read all the subelements of the key class # First read all the subelements of the key class
for child in zkhandler.zk_conn.get_children(self.path(f'base.{elem}')): for child in zkhandler.zk_conn.get_children(self.path(f'base.{elem}')):
# For each key in the schema for that particular elem # For each key in the schema for that particular elem
@ -850,7 +856,7 @@ class ZKSchema(object):
data = '' data = ''
zkhandler.zk_conn.create(self.path(kpath), data.encode(zkhandler.encoding)) zkhandler.zk_conn.create(self.path(kpath), data.encode(zkhandler.encoding))
for elem in ['node', 'domain', 'network', 'osd', 'pool']: for elem in ['logs', 'node', 'domain', 'network', 'osd', 'pool']:
# First read all the subelements of the key class # First read all the subelements of the key class
for child in zkhandler.zk_conn.get_children(self.path(f'base.{elem}')): for child in zkhandler.zk_conn.get_children(self.path(f'base.{elem}')):
# For each key in the schema for that particular elem # For each key in the schema for that particular elem

View File

@ -140,6 +140,8 @@ pvc:
file_logging: True file_logging: True
# stdout_logging: Enable or disable logging to stdout (i.e. journald) # stdout_logging: Enable or disable logging to stdout (i.e. journald)
stdout_logging: True stdout_logging: True
# zookeeper_logging: Enable ot disable logging to Zookeeper (for `pvc node log` functionality)
zookeeper_logging: True
# log_colours: Enable or disable ANSI colours in log output # log_colours: Enable or disable ANSI colours in log output
log_colours: True log_colours: True
# log_dates: Enable or disable date strings in log output # log_dates: Enable or disable date strings in log output
@ -152,10 +154,12 @@ pvc:
log_keepalive_storage_details: True log_keepalive_storage_details: True
# console_log_lines: Number of console log lines to store in Zookeeper per VM # console_log_lines: Number of console log lines to store in Zookeeper per VM
console_log_lines: 1000 console_log_lines: 1000
# node_log_lines: Number of node log lines to store in Zookeeper per node
node_log_lines: 2000
# networking: PVC networking configuration # networking: PVC networking configuration
# OPTIONAL if enable_networking: False # OPTIONAL if enable_networking: False
networking: networking:
# bridge_device: Underlying device to use for bridged vLAN networks; usually the device underlying <cluster> # bridge_device: Underlying device to use for bridged vLAN networks; usually the device of <cluster>
bridge_device: ens4 bridge_device: ens4
# sriov_enable: Enable or disable (default if absent) SR-IOV network support # sriov_enable: Enable or disable (default if absent) SR-IOV network support
sriov_enable: False sriov_enable: False

View File

@ -158,12 +158,14 @@ def readConfig(pvcnoded_config_file, myhostname):
'console_log_directory': o_config['pvc']['system']['configuration']['directories']['console_log_directory'], 'console_log_directory': o_config['pvc']['system']['configuration']['directories']['console_log_directory'],
'file_logging': o_config['pvc']['system']['configuration']['logging']['file_logging'], 'file_logging': o_config['pvc']['system']['configuration']['logging']['file_logging'],
'stdout_logging': o_config['pvc']['system']['configuration']['logging']['stdout_logging'], 'stdout_logging': o_config['pvc']['system']['configuration']['logging']['stdout_logging'],
'zookeeper_logging': o_config['pvc']['system']['configuration']['logging'].get('zookeeper_logging', False),
'log_colours': o_config['pvc']['system']['configuration']['logging']['log_colours'], 'log_colours': o_config['pvc']['system']['configuration']['logging']['log_colours'],
'log_dates': o_config['pvc']['system']['configuration']['logging']['log_dates'], 'log_dates': o_config['pvc']['system']['configuration']['logging']['log_dates'],
'log_keepalives': o_config['pvc']['system']['configuration']['logging']['log_keepalives'], 'log_keepalives': o_config['pvc']['system']['configuration']['logging']['log_keepalives'],
'log_keepalive_cluster_details': o_config['pvc']['system']['configuration']['logging']['log_keepalive_cluster_details'], 'log_keepalive_cluster_details': o_config['pvc']['system']['configuration']['logging']['log_keepalive_cluster_details'],
'log_keepalive_storage_details': o_config['pvc']['system']['configuration']['logging']['log_keepalive_storage_details'], 'log_keepalive_storage_details': o_config['pvc']['system']['configuration']['logging']['log_keepalive_storage_details'],
'console_log_lines': o_config['pvc']['system']['configuration']['logging']['console_log_lines'], 'console_log_lines': o_config['pvc']['system']['configuration']['logging']['console_log_lines'],
'node_log_lines': o_config['pvc']['system']['configuration']['logging'].get('node_log_lines', 0),
'vm_shutdown_timeout': int(o_config['pvc']['system']['intervals']['vm_shutdown_timeout']), 'vm_shutdown_timeout': int(o_config['pvc']['system']['intervals']['vm_shutdown_timeout']),
'keepalive_interval': int(o_config['pvc']['system']['intervals']['keepalive_interval']), 'keepalive_interval': int(o_config['pvc']['system']['intervals']['keepalive_interval']),
'fence_intervals': int(o_config['pvc']['system']['intervals']['fence_intervals']), 'fence_intervals': int(o_config['pvc']['system']['intervals']['fence_intervals']),