Log vm provisioning times

VM provisioning times can serve as a good indicator of potential
problems, such as capacity issues. Currently, when a customer claims
their VM provisioning is slow, we must download logs and parse them
using ad-hoc scripts.

This new log line will help to identify slow VM provisioning more
easily. When we search for `provision.duration:>30`, it will display VM
provisioning durations longer than 30 seconds.

prog/vm/nexus.rb

@@ -299,6 +299,7 @@ def before_run
     out = `ssh -o BatchMode=yes -o ConnectTimeout=1 -o PreferredAuthentications=none user@#{addr} 2>&1`
     if out.include? "Host key verification failed."
       vm.update(display_state: "running")
+      Clog.emit("vm provisioned") { {vm: vm.values, provision: {vm_ubid: vm.ubid, vm_host_ubid: host.ubid, duration: Time.now - vm.created_at}} }
       hop_wait
     end
     nap 1

spec/prog/vm/nexus_spec.rb

@@ -396,14 +396,19 @@ def new_host(**args)
     end
 
     it "hops to wait if sshable" do
+      expect(vm).to receive(:created_at).and_return(Time.now)
+      expect(vm).to receive(:vm_host).and_return(instance_double(VmHost, ubid: "vhhqmsyfvzpy2q9gqb5h0mpde2"))
       vm_addr = instance_double(AssignedVmAddress, id: "46ca6ded-b056-4723-bd91-612959f52f6f", ip: NetAddr::IPv4Net.parse("10.0.0.1"))
       expect(vm).to receive(:assigned_vm_address).and_return(vm_addr).at_least(:once)
       expect(nx).to receive(:`).with("ssh -o BatchMode=yes -o ConnectTimeout=1 -o PreferredAuthentications=none user@10.0.0.1 2>&1").and_return("Host key verification failed.")
       expect(vm).to receive(:update).with(display_state: "running").and_return(true)
+      expect(Clog).to receive(:emit).with("vm provisioned").and_call_original
       expect { nx.wait_sshable }.to hop("wait")
     end
 
     it "uses ipv6 if ipv4 is not enabled" do
+      expect(vm).to receive(:created_at).and_return(Time.now)
+      expect(vm).to receive(:vm_host).and_return(instance_double(VmHost, ubid: "vhhqmsyfvzpy2q9gqb5h0mpde2"))
       expect(vm).to receive(:ephemeral_net6).and_return(NetAddr::IPv6Net.parse("2a01:4f8:10a:128b:3bfa::/79"))
       expect(nx).to receive(:`).with("ssh -o BatchMode=yes -o ConnectTimeout=1 -o PreferredAuthentications=none user@2a01:4f8:10a:128b:3bfa::2 2>&1").and_return("Host key verification failed.")
       expect(vm).to receive(:update).with(display_state: "running").and_return(true)