Clog improvements

lib/clog.rb

@@ -7,11 +7,24 @@ class Clog
 
   def self.emit(message)
     out = if block_given?
-      case v = yield
+      case metadata = yield
       when Hash
-        v
+        metadata
+      when Array
+        metadata.reduce({}) do |hash, item|
+          case item
+          when Hash
+            hash.merge(item)
+          when Sequel::Model
+            hash.merge(serialize_model(item))
+          else
+            hash.merge({invalid_type: item.class.to_s})
+          end
+        end
+      when Sequel::Model
+        serialize_model(metadata)
       else
-        {invalid_type: v.class.to_s}
+        {invalid_type: metadata.class.to_s}
       end
     else
       {}
@@ -31,4 +44,8 @@ def self.emit(message)
     end
     nil
   end
+
+  private_class_method def self.serialize_model(model)
+    {model.class.table_name => model.values.except(*model.class.redacted_columns)}
+  end
 end

model/strand.rb

@@ -79,7 +79,7 @@ def load(snap = nil)
   def unsynchronized_run
     start_time = Time.now
     prog_label = "#{prog}.#{label}"
-    Clog.emit("starting strand") { {strand: values, strand_started: {delay: start_time - schedule, prog_label: prog_label}} }
+    Clog.emit("starting strand") { [self, {strand_started: {delay: start_time - schedule, prog_label: prog_label}}] }
 
     if label == stack.first["deadline_target"].to_s
       if (pg = Page.from_tag_parts("Deadline", id, prog, stack.first["deadline_target"]))
@@ -141,7 +141,7 @@ def unsynchronized_run
       fail "BUG: Prog #{prog}##{label} did not provide flow control"
     end
   ensure
-    Clog.emit("finished strand") { {strand: values, strand_finished: {duration: Time.now - start_time, prog_label: prog_label}} }
+    Clog.emit("finished strand") { [self, {strand_finished: {duration: Time.now - start_time, prog_label: prog_label}}] }
   end
 
   def run(seconds = 0)

prog/vm/github_runner.rb

@@ -137,11 +137,11 @@ def before_run
     }.first.to_f
 
     unless utilization < 70
-      Clog.emit("Waiting for customer concurrency limit, utilization is high") { {github_runner: github_runner.values, utilization: utilization} }
+      Clog.emit("Waiting for customer concurrency limit, utilization is high") { [github_runner, {utilization: utilization}] }
       nap rand(5..15)
     end
 
-    Clog.emit("Concurrency limit reached but allocation is allowed because of low utilization") { {github_runner: github_runner.values, utilization: utilization} }
+    Clog.emit("Concurrency limit reached but allocation is allowed because of low utilization") { [github_runner, {utilization: utilization}] }
 
     hop_allocate_vm
   end
@@ -244,14 +244,14 @@ def setup_info
     # If the runner script is not started yet, we can delete the runner and
     # register it again.
     if vm.sshable.cmd("systemctl show -p SubState --value runner-script").chomp == "dead"
-      Clog.emit("Deregistering runner because it already exists") { {github_runner: github_runner.values.merge({runner_id: runner_id})} }
+      Clog.emit("Deregistering runner because it already exists") { [github_runner, {existing_runner: {runner_id: runner_id}}] }
       github_client.delete("/repos/#{github_runner.repository_name}/actions/runners/#{runner_id}")
       nap 5
     end
 
     # The runner script is already started. We persist the runner_id and allow
     # wait label to decide the next step.
-    Clog.emit("The runner already exists but the runner script is started too") { {github_runner: github_runner.values.merge({runner_id: runner_id})} }
+    Clog.emit("The runner already exists but the runner script is started too") { [github_runner, {existing_runner: {runner_id: runner_id}}] }
     github_runner.update(runner_id: runner_id, ready_at: Time.now)
     hop_wait
   end
@@ -262,7 +262,7 @@ def setup_info
       github_runner.incr_destroy
       nap 15
     when "failed"
-      Clog.emit("The runner script failed") { {github_runner: github_runner.values} }
+      Clog.emit("The runner script failed") { github_runner }
       github_runner.provision_spare_runner
       github_runner.incr_destroy
       nap 0
@@ -274,7 +274,7 @@ def setup_info
     if github_runner.workflow_job.nil? && Time.now > github_runner.ready_at + 5 * 60
       response = github_client.get("/repos/#{github_runner.repository_name}/actions/runners/#{github_runner.runner_id}")
       unless response[:busy]
-        Clog.emit("The runner does not pick a job") { {github_runner: github_runner.values} }
+        Clog.emit("The runner does not pick a job") { github_runner }
         github_runner.incr_destroy
         nap 0
       end
@@ -317,7 +317,7 @@ def setup_info
           # Exclude the "Started" line because it contains sensitive information.
           vm.sshable.cmd("journalctl -u runner-script --no-pager | grep -v -e Started -e sudo")
         rescue Sshable::SshError
-          Clog.emit("Failed to move serial.log or running journalctl") { {github_runner: github_runner.values} }
+          Clog.emit("Failed to move serial.log or running journalctl") { github_runner }
         end
       end
       vm.incr_destroy

prog/vm/host_nexus.rb

@@ -228,7 +228,7 @@ def before_run
     end
 
     unless vm_host.vms.empty?
-      Clog.emit("Cannot destroy the vm host with active virtual machines, first clean them up") { {vm_host: vm_host.values} }
+      Clog.emit("Cannot destroy the vm host with active virtual machines, first clean them up") { vm_host }
       nap 15
     end
 

prog/vm/nexus.rb

@@ -272,7 +272,7 @@ def write_params_json
 
   label def create_billing_record
     vm.update(display_state: "running", provisioned_at: Time.now)
-    Clog.emit("vm provisioned") { {vm: vm.values, provision: {vm_ubid: vm.ubid, vm_host_ubid: host.ubid, duration: Time.now - vm.allocated_at}} }
+    Clog.emit("vm provisioned") { [vm, {provision: {vm_ubid: vm.ubid, vm_host_ubid: host.ubid, duration: Time.now - vm.created_at}}] }
     project = vm.projects.first
     hop_wait unless project.billable
 

prog/vnet/nic_nexus.rb

@@ -111,7 +111,7 @@ def before_run
 
   label def destroy
     if nic.vm
-      Clog.emit("Cannot destroy nic with active vm, first clean up the attached resources") { {nic: nic.values} }
+      Clog.emit("Cannot destroy nic with active vm, first clean up the attached resources") { nic }
       nap 5
     end
 

prog/vnet/subnet_nexus.rb

@@ -130,9 +130,7 @@ def gen_reqid
     if private_subnet.nics.any? { |n| !n.vm_id.nil? }
       register_deadline(nil, 10 * 60, allow_extension: true) if private_subnet.nics.any? { |n| n.vm&.prevent_destroy_set? }
 
-      Clog.emit "Cannot destroy subnet with active nics, first clean up the attached resources" do
-        {private_subnet: private_subnet.values}
-      end
+      Clog.emit("Cannot destroy subnet with active nics, first clean up the attached resources") { private_subnet }
 
       nap 5
     end

spec/lib/clog_spec.rb

@@ -25,4 +25,15 @@
     expect($stdout).to receive(:write).with('{"invalid_type":"Integer","message":"ngmi","time":"' + now.to_s + '"}' + "\n")
     described_class.emit("ngmi") { 1 }
   end
+
+  it "returns the key with redacted values for Sequel::Model" do
+    expect($stdout).to receive(:write).with('{"vm":{"id":"123"},"message":"model","time":"' + now.to_s + '"}' + "\n")
+    described_class.emit("model") { Vm.new(public_key: "redacted_key").tap { _1.id = "123" } }
+  end
+
+  it "returns a combined hash when the metadata is an array" do
+    expect($stdout).to receive(:write).with('{"vm":{"id":"123"},"field1":"custom","invalid_type":"String","message":"model","time":"' + now.to_s + '"}' + "\n")
+    vm = Vm.new(public_key: "redacted_key").tap { _1.id = "123" }
+    described_class.emit("model") { [vm, {field1: "custom"}, "invalid"] }
+  end
 end

spec/prog/vm/host_nexus_spec.rb

@@ -272,7 +272,6 @@
 
     it "waits draining" do
       expect(vm_host).to receive(:allocation_state).and_return("draining")
-      expect(vm_host).to receive(:values).and_return({allocation_state: "draining"})
       expect(Clog).to receive(:emit).with("Cannot destroy the vm host with active virtual machines, first clean them up").and_call_original
       expect { nx.destroy }.to nap(15)
     end