Merge ~hyask/autopkgtest-cloud:skia/fix_metrics into autopkgtest-cloud:master

[Skia]

Two small fixes for issues I've seen on LXD worker.

[Tim Andersson (andersson123)]

in my mp, I amended the script to not run as tuples so I'm confused by your most recent commit. The other commit looks good to me know, although CI has also failed.

review: Needs Fixing

[Tim Andersson (andersson123)]

but I understand what you mean r.e. the tuple now. Accessing with an index isn't great and I should've caught that, my bad. I'll approve this once CI passes, LGTM!

review: Needs Fixing

[Skia (hyask)]

CI failure doesn't look related to my changes.

[Tim Andersson (andersson123)]

CI failure seems to be a tempfail - I've seen it in other recent MP's, but not all. I'll approve this, and let's keep our eyes out for this tempfail again.

[Tim Andersson (andersson123)]

review: Approve

[Tim Andersson (andersson123)]

review: Approve

[Tim Andersson (andersson123)]

I think we can just say measurements sent without having the whole measurements dict in journalctl. This service runs quite often so that'll be a lot of logspam. But this is just my opinion. Otherwise, looks good to me!

review: Needs Fixing

[Skia (hyask)]

I agree, this would make a lot of noise, that's why I set those logs as `debug`, while the log level is `info`. This just makes it easy to cowboy the debug level when in need, but theses lines are not active on the default version of that script :-)

https://docs.python.org/3/library/logging.html#levels

[Skia (hyask)]

Here is an example run in debug mode:
```
systemd[1]: Starting Collect & submit metrics...
metrics[3587355]: INFO:__main__:Collecting units metrics
metrics[3587355]: DEBUG:__main__:measurements: [{'measurement': 'autopkgtest_unit_status', 'fields': {'count': 39}, 'tags': {'arch': 'armhf', 'status': 'active', 'instance': 'production'}}, {'measurement': 'autopkgtest_unit_status', 'fields': {'count': 54}, 'tags': {'arch': 'armhf', 'status': 'error', 'instance': 'production'}}]
metrics[3587355]: INFO:__main__:Collecting remotes metrics
metrics[3587355]: WARNING:__main__:remote error: CalledProcessError(1, ['lxc', 'list', 'lxd-armhf-10.145.243.125:'])
metrics[3587355]: WARNING:__main__:remote error: CalledProcessError(1, ['lxc', 'list', 'lxd-armhf-10.145.243.137:'])
metrics[3587355]: WARNING:__main__:remote error: CalledProcessError(1, ['lxc', 'list', 'lxd-armhf-10.145.243.233:'])
metrics[3587355]: WARNING:__main__:remote error: CalledProcessError(1, ['lxc', 'list', 'lxd-armhf-10.145.243.237:'])
metrics[3587355]: WARNING:__main__:remote error: CalledProcessError(1, ['lxc', 'list', 'lxd-armhf-10.145.243.59:'])
metrics[3587355]: WARNING:__main__:remote error: CalledProcessError(1, ['lxc', 'list', 'lxd-armhf-10.44.124.111:'])
metrics[3587355]: WARNING:__main__:remote error: CalledProcessError(1, ['lxc', 'list', 'lxd-armhf-10.44.124.162:'])
metrics[3587355]: WARNING:__main__:remote error: CalledProcessError(1, ['lxc', 'list', 'lxd-armhf-10.44.124.24:'])
metrics[3587355]: DEBUG:__main__:measurements: [{'measurement': 'autopkgtest_cluster_status', 'fields': {'count': 0}, 'tags': {'arch': 'armhf', 'status': 'active', 'instance': 'production'}}, {'measurement': 'autopkgtest_cluster_status', 'fields': {'count': 0}, 'tags': {'arch': 'armhf', 'status': 'error', 'instance': 'production'}}]
metrics[3587355]: DEBUG:__main__:measurements: [{'measurement': 'autopkgtest_lxd_status', 'fields': {'count': 24}, 'tags': {'arch': 'armhf', 'status': 'active', 'instance': 'production'}}, {'measurement': 'autopkgtest_lxd_status', 'fields': {'count': 8}, 'tags': {'arch': 'armhf', 'status': 'error', 'instance': 'production'}}]
metrics[3587355]: DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): ubuntu-release-kpi-influx.internal:8086
metrics[3587355]: DEBUG:urllib3.connectionpool:http://ubuntu-release-kpi-influx.internal:8086 "POST /write?db=metrics HTTP/1.1" 204 0
systemd[1]: metrics.service: Succeeded.
systemd[1]: Finished Collect & submit metrics.
```
Default level is even less verbose, so I think we're good, even if this run every 5 minutes.

[Tim Andersson (andersson123)]

ah I missed that, mb, LGTM

review: Approve

diff --git a/charms/focal/autopkgtest-cloud-worker/autopkgtest-cloud/tools/metrics b/charms/focal/autopkgtest-cloud-worker/autopkgtest-cloud/tools/metrics
index 90ca1a3..28c5aa7 100755
--- a/charms/focal/autopkgtest-cloud-worker/autopkgtest-cloud/tools/metrics
+++ b/charms/focal/autopkgtest-cloud-worker/autopkgtest-cloud/tools/metrics
@@ -1,6 +1,7 @@
 #!/usr/bin/python3
 
 import json
+import logging
 import os
 import subprocess
 
@@ -18,6 +19,9 @@ INFLUXDB_PASSWORD = os.environ["INFLUXDB_PASSWORD"]
 INFLUXDB_PORT = os.environ["INFLUXDB_PORT"]
 INFLUXDB_USERNAME = os.environ["INFLUXDB_USERNAME"]
 
+logger = logging.getLogger(__name__)
+logging.basicConfig(level=logging.INFO)
+
 
 def make_submission(counts, measurement):
     out = []
@@ -43,10 +47,12 @@ def make_submission(counts, measurement):
             },
         }
         out.append(m)
+    logger.debug("measurements sent: %s", out)
     return out
 
 
 def get_units():
+    logger.info("Collecting units")
     counts = {}
 
     (units,) = SYSTEM_BUS.call_sync(
@@ -111,6 +117,7 @@ def get_list_of_intended_remote_ips(arch):
 
 
 def get_remotes():
+    logger.info("Collecting remotes")
     cluster_counts = {}
     noncluster_counts = {}
     out = subprocess.check_output(
@@ -155,8 +162,12 @@ def get_remotes():
                 )
                 noncluster_counts[arch][0] += 1
                 functional_ips.append(r.replace(prefix, ""))
-            except subprocess.CalledProcessError:
-                noncluster_counts[arch][0] += 1
+            except (
+                subprocess.CalledProcessError,
+                subprocess.TimeoutExpired,
+            ) as e:
+                logger.warning("remote error: %s", repr(e))
+                noncluster_counts[arch][1] += 1
 
     cluster_status = make_submission(
         cluster_counts, "autopkgtest_cluster_status"