From 780789c6c233ace56dd293813dd749edcada44db Mon Sep 17 00:00:00 2001 From: Wojciech Kosior Date: Tue, 16 Jun 2020 22:20:03 +0200 Subject: move logging to ztdnslib.py --- src/hourly.py | 74 +++++++++++++++++++++++++-------------------------------- src/ztdnslib.py | 13 ++++++++++ 2 files changed, 46 insertions(+), 41 deletions(-) diff --git a/src/hourly.py b/src/hourly.py index bb95fe7..95680a5 100755 --- a/src/hourly.py +++ b/src/hourly.py @@ -10,7 +10,7 @@ import psycopg2 # our own module used by several scripts in the project from ztdnslib import start_db_connection, \ - get_default_host_address, get_ztdns_config + get_default_host_address, get_ztdns_config, log wrapper = '/var/lib/0tdns/vpn_wrapper.sh' perform_queries = '/var/lib/0tdns/perform_queries.py' @@ -97,7 +97,7 @@ def number_to_ip_address(number): # Addressess ending with .16 (subnet address) # and .19 (broadcast in the subnet) are considered unusable in this case. # The returned set will contain up to count elements. -def get_available_subnetworks(count, address_ranges, logfile): +def get_available_subnetworks(count, address_ranges): available_subnetworks = set() for address_range in address_ranges: @@ -122,8 +122,8 @@ def get_available_subnetworks(count, address_ranges, logfile): end_addr_number -= 1 if start_addr_number >= end_addr_number: - logfile.write("address range '{}' doesn't contain any" - " /30 subnetworks\n".format(address_range)) + log("address range '{}' doesn't contain any /30 subnetworks"\ + .format(address_range)) else: while len(available_subnetworks) < count and \ start_addr_number < end_addr_number: @@ -132,15 +132,14 @@ def get_available_subnetworks(count, address_ranges, logfile): available_subnetworks.add((usable_addr1, usable_addr2)) start_addr_number += 4 else: - logfile.write("'{}' is not a valid address range\n"\ - .format(address_range)) + log("'{}' is not a valid address range".format(address_range)) return available_subnetworks -def do_hourly_work(hour, logfile): +def do_hourly_work(hour): ztdns_config = get_ztdns_config() if ztdns_config['enabled'] != 'yes': - logfile.write("0tdns not enabled in the config - exiting\n") + log('0tdns not enabled in the config - exiting') return connection = start_db_connection(ztdns_config) @@ -150,7 +149,7 @@ def do_hourly_work(hour, logfile): handled_vpns = ztdns_config.get('handled_vpns') if handled_vpns: - logfile.write("Only handling vpns of ids {}\n".format(handled_vpns)) + log('Only handling vpns of ids {}'.format(handled_vpns)) vpns = [vpn for vpn in vpns if vpn[0] in handled_vpns] else: # if not specfied in the config, all vpns are handled @@ -158,26 +157,25 @@ def do_hourly_work(hour, logfile): parallel_vpns = ztdns_config['parallel_vpns'] # we need this many subnets subnets = get_available_subnetworks(parallel_vpns, - ztdns_config['private_addresses'], - logfile) + ztdns_config['private_addresses']) if not subnets: - logfile.write("couldn't get ANY /30 subnet of private addresses from" - " the 0tdns config file - exiting\n"); + log("couldn't get ANY /30 subnet of private" + " addresses from the 0tdns config file - exiting"); return # TODO close cursor and connection here if len(subnets) < parallel_vpns: - logfile.write("configuration allows running {0} parallel vpn" - " connections, but provided private ip addresses give" - " only {1} /30 subnets, which limits parallel connections" - " to {1}\n".format(parallel_vpns, len(subnets))) + log('configuration allows running {0} parallel vpn connections, but' + ' provided private ip addresses give only {1} /30 subnets, which' + ' limits parallel connections to {1}'\ + .format(parallel_vpns, len(subnets))) parallel_vpns = len(subnets) for vpn_id, config_hash in vpns: config_path = "/var/lib/0tdns/{}.ovpn".format(config_hash) if not path.isfile(config_path): - logfile.write("Syncing config for vpn {} with hash {}\n"\ - .format(vpn_id, config_hash)) + log('Syncing config for vpn {} with hash {}'\ + .format(vpn_id, config_hash)) sync_ovpn_config(cursor, vpn_id, config_path, config_hash) # map of each wrapper pid to tuple containing id of the vpn it connects to @@ -195,13 +193,11 @@ def do_hourly_work(hour, logfile): if exit_status != 0: if exit_status == 2: # this means our perform_queries.py crashed... not good - logfile.write('performing queries through vpn {} failed\n'\ - .format(vpn_id)) + log('performing queries through vpn {} failed'.format(vpn_id)) result_info = 'internal failure: process_crash' else: # vpn server is probably not responding - logfile.write('connection to vpn {} failed\n'\ - .format(vpn_id)) + log('connection to vpn {} failed'.format(vpn_id)) result_info = 'internal failure: vpn_connection_failure' try: @@ -214,8 +210,7 @@ def do_hourly_work(hour, logfile): WHERE vpn_id = %s); ''', (hour, result_info, vpn_id)) except psycopg2.IntegrityError: - logfile.write('results already exist for vpn {}\n'\ - .format(vpn_id)) + log('results already exist for vpn {}'.format(vpn_id)) pids_wrappers.pop(pid) subnets.add(subnet) @@ -230,7 +225,7 @@ def do_hourly_work(hour, logfile): veth_addr1, veth_addr2 = subnet route_through_veth = ztdns_config['host'] + "/32" command_in_namespace = [perform_queries, hour, str(vpn_id)] - logfile.write("Running connection for vpn {}\n".format(vpn_id)) + log('Running connection for vpn {}'.format(vpn_id)) # see into vpn_wrapper.sh for explaination of its arguments p = subprocess.Popen([wrapper, config_path, physical_ip, veth_addr1, @@ -250,19 +245,16 @@ def do_hourly_work(hour, logfile): connection.close() -with open("/var/log/0tdns.log", "a") as logfile: - # round down to an hour - this datetime format is one - # of the formats accepted by postgres - hour = strftime('%Y-%m-%d %H:00%z', gmtime()) - if not lock_on_file(): - logfile.write("Failed trying to run for {}; {} exists\n"\ - .format(hour, lockfile)) - else: - try: - logfile.write("Running for {}\n".format(hour)) - do_hourly_work(hour, logfile) - finally: - if not unlock_on_file(): - logfile.write("Can't remove lock - {} already deleted!\n"\ - .format(lockfile)) +# round down to an hour - this datetime format is one +# of the formats accepted by postgres +hour = strftime('%Y-%m-%d %H:00%z', gmtime()) +if not lock_on_file(): + log('Failed trying to run for {}; {} exists'.format(hour, lockfile)) +else: + try: + log('Running for {}'.format(hour)) + do_hourly_work(hour) + finally: + if not unlock_on_file(): + log("Can't remove lock - {} already deleted!".format(lockfile)) diff --git a/src/ztdnslib.py b/src/ztdnslib.py index 34e1e00..dc54602 100644 --- a/src/ztdnslib.py +++ b/src/ztdnslib.py @@ -1,7 +1,10 @@ import yaml import psycopg2 +import os +import fcntl db_config_path = '/etc/0tdns/db_connection_config.yml' +logfile = '/var/log/0tdns.log' def get_ztdns_config(): return yaml.safe_load(open(db_config_path, 'r')) @@ -24,3 +27,13 @@ def get_default_host_address(remote_address): hostaddr = s.getsockname()[0] s.close() return hostaddr + +def log(msg): + msg = bytearray(msg + '\n', "UTF-8") + fd = os.open(logfile, os.O_APPEND | os.O_WRONLY | os.O_CREAT) + try: + fcntl.flock(fd, fcntl.LOCK_EX) + os.write(fd, msg) + fcntl.flock(fd, fcntl.LOCK_UN) + finally: + os.close(fd) -- cgit v1.2.3