Merge ~sajoupa/apt-stresstest-charm:logging into apt-stresstest-charm:master

[Laurent Sesquès]

Add basic logging - no logrotate for now

[Laurent Sesquès (sajoupa)]

This will allow logging but lacks log rotation. Submitting the MP to record that code which I successfully used to troubleshoot an issue, but setting it to WIP because we need log rotation before merging.

[Benjamin Allot (ballot)]

LGTM so far

[Haw Loeung (hloeung)]

We can add logrotation later, LGTM.

review: Approve (+1)

[🤖 Canonical IS Merge Bot (canonical-is-mergebot)]

This merge proposal is being monitored by mergebot. Change the status to Approved to merge.

[🤖 Canonical IS Merge Bot (canonical-is-mergebot)]

Change successfully merged at revision 1ef78810095364cba108403d2db4772e608be795

diff --git a/files/test_apt_mirrors.py b/files/test_apt_mirrors.py
index 75d14fe..0cc583a 100755
--- a/files/test_apt_mirrors.py
+++ b/files/test_apt_mirrors.py
@@ -20,12 +20,22 @@
 import argparse
 import datetime
 import glob
+import logging
 import os
 import socket
 import subprocess
 import sys
 from yaml import safe_load
 
+LOGFILE = '/var/log/apt-stresstest.log'
+
+file_handler = logging.FileHandler(LOGFILE)
+file_handler.setLevel(logging.INFO)
+basic_formatter = logging.Formatter('%(asctime)s - %(message)s')
+file_handler.setFormatter(basic_formatter)
+log = logging.getLogger('apt-stresstest')
+log.setLevel(logging.INFO)
+log.addHandler(file_handler)
 
 class Timer(object):
     def __init__(self):
@@ -170,17 +180,21 @@ def output_results(result, verbose=False, send_to=None):
 
 def run_tests(domain, ip, packages, args):
 
+    log.info("Running apt update 1 and sending to telegraf")
     output_results(render_influx("update_1", domain, ip,
                    apt_update(ip, timeout=args.update_timeout)),
                    verbose=args.verbose, send_to=args.send_to)
+    log.info("Running apt update 2 and sending to telegraf")
     output_results(render_influx("update_2", domain, ip,
                    apt_update(ip, timeout=args.update_timeout)),
                    verbose=args.verbose, send_to=args.send_to)
     for index, package in enumerate(packages):
+        log.info("Performing cached download of {} - {} and sending to telegraf".format(1 + index, package))
         test_name = "cached_download_{}_{}".format(1 + index, package)
         output_results(render_influx(test_name, domain, ip,
                        apt_download(package, ip, timeout=args.download_timeout)),
                        verbose=args.verbose, send_to=args.send_to)
+        log.info("Performing uncached download of {} - {} and sending to telegraf".format(1 + index, package))
         test_name = "uncached_download_{}_{}".format(1 + index, package)
         output_results(render_influx(test_name, domain, ip,
                        apt_download(package, ip, no_cache=True, timeout=args.download_timeout)),
@@ -234,6 +248,7 @@ def write_apt_config(domain, ip, series=None):
 
 
 def main():
+    log.info("Beginning apt-stresstest run...")
     timer = Timer()
     timer.start()
     args = parse_args()
@@ -245,17 +260,20 @@ def main():
 
     for ip in ips:
         write_apt_config(domain, ip, args.series)
+        log.info("apt config written for {} - {}. Running tests now.".format(domain, ip))
         run_tests(
             domain=domain,
             ip=ip,
             packages=args.package.split(','),
             args=args,
         )
+    log.info("Tests done, stopping timer.")
     timer.stop()
     output_results(render_influx("N/A", "N/A", "N/A", timer.time, "apt_transaction_total_duration_seconds"),
                    verbose=args.verbose, send_to=args.send_to)
     output_results(render_influx("N/A", "N/A", "N/A", len(ips), "apt_mirror_units_count"),
                    verbose=args.verbose, send_to=args.send_to)
+    log.info("Pushed global timer and units count to telegraf.")
 
 
 if __name__ == '__main__':