From f080776c1de041fca8ea8b4695a1319bc70bdb5d Mon Sep 17 00:00:00 2001
From: "James E. Blair" <jeblair@redhat.com>
Date: Thu, 27 Sep 2018 12:50:15 -0700
Subject: [PATCH] Provide some accounting of node usage in logs

It would be good to provide this information in other ways (e.g.,
statsd, SQL), but for now, try to at least emit some useful accounting
information that can be collected from logs.

Change-Id: Ic12d91940bdd4b5a81596627d7544015df5eba09
---
 zuul/manager/__init__.py |  2 +-
 zuul/model.py            |  2 +-
 zuul/nodepool.py         | 12 +++++++++++-
 zuul/scheduler.py        |  2 +-
 4 files changed, 14 insertions(+), 4 deletions(-)

diff --git a/zuul/manager/__init__.py b/zuul/manager/__init__.py
index 4d16042b0b..b442fcd2e8 100644
--- a/zuul/manager/__init__.py
+++ b/zuul/manager/__init__.py
@@ -396,7 +396,7 @@ class PipelineManager(object):
 
             if not was_running:
                 nodeset = build.build_set.getJobNodeSet(build.job.name)
-                self.sched.nodepool.returnNodeSet(nodeset)
+                self.sched.nodepool.returnNodeSet(nodeset, build)
             build.result = 'CANCELED'
             canceled = True
             canceled_jobs.add(build.job.name)
diff --git a/zuul/model.py b/zuul/model.py
index eddf5af707..ca6af5b43e 100644
--- a/zuul/model.py
+++ b/zuul/model.py
@@ -679,7 +679,7 @@ class NodeSet(ConfigObject):
             name = self.name + ' '
         else:
             name = ''
-        return '<NodeSet %s%s%s>' % (name, self.nodes, self.groups)
+        return '<NodeSet %s%s>' % (name, list(self.nodes.values()))
 
     def __len__(self):
         return len(self.nodes)
diff --git a/zuul/nodepool.py b/zuul/nodepool.py
index a8ffe4bfb7..68f9629aab 100644
--- a/zuul/nodepool.py
+++ b/zuul/nodepool.py
@@ -120,8 +120,18 @@ class Nodepool(object):
             node.state = model.STATE_IN_USE
             self.sched.zk.storeNode(node)
 
-    def returnNodeSet(self, nodeset):
+    def returnNodeSet(self, nodeset, build=None):
         self.log.info("Returning nodeset %s" % (nodeset,))
+        if (build and build.start_time and build.end_time and
+            build.build_set and build.build_set.item and
+            build.build_set.item.change and
+            build.build_set.item.change.project):
+            duration = build.end_time - build.start_time
+            project = build.build_set.item.change.project
+            self.log.info("Nodeset %s with %s nodes was in use "
+                          "for %s seconds for build %s for project %s",
+                          nodeset, len(nodeset.nodes), duration, build,
+                          project)
         for node in nodeset.getNodes():
             if node.lock is None:
                 self.log.error("Node %s is not locked" % (node,))
diff --git a/zuul/scheduler.py b/zuul/scheduler.py
index ed27c430a9..9724b84a51 100644
--- a/zuul/scheduler.py
+++ b/zuul/scheduler.py
@@ -1218,7 +1218,7 @@ class Scheduler(threading.Thread):
         except Exception:
             self.log.exception("Unable to process autohold for %s" % build)
         try:
-            self.nodepool.returnNodeSet(build.nodeset)
+            self.nodepool.returnNodeSet(build.nodeset, build)
         except Exception:
             self.log.exception("Unable to return nodeset %s" % build.nodeset)