Get QEMU logs from virtlogd

cmd/virt-launcher/virt-launcher.go

@@ -347,7 +347,9 @@ func main() {
 		panic(err)
 	}
 	util.StartLibvirt(stopChan)
-	util.StartVirtlog(stopChan)
+	// only single domain should be present
+	domainName := api.VMINamespaceKeyFunc(vm)
+	util.StartVirtlog(stopChan, domainName)
 
 	domainConn := createLibvirtConnection()
 	defer domainConn.Close()
@@ -362,9 +364,6 @@ func main() {
 		panic(err)
 	}
 
-	// only single domain should be present
-	domainName := api.VMINamespaceKeyFunc(vm)
-
 	// Start the virt-launcher command service.
 	// Clients can use this service to tell virt-launcher
 	// to start/stop virtual machines

pkg/virt-launcher/virtwrap/util/libvirt_helper.go

@@ -230,7 +230,7 @@ func StartLibvirt(stopChan chan struct{}) {
 	}()
 }
 
-func StartVirtlog(stopChan chan struct{}) {
+func StartVirtlog(stopChan chan struct{}, domainName string) {
 	go func() {
 		for {
 			var args []string
@@ -242,10 +242,40 @@ func StartVirtlog(stopChan chan struct{}) {
 
 			err := cmd.Start()
 			if err != nil {
-				log.Log.Reason(err).Error("failed to start libvirtd")
+				log.Log.Reason(err).Error("failed to start virtlogd")
 				panic(err)
 			}
 
+			go func() {
+				logfile := fmt.Sprintf("/var/log/libvirt/qemu/%s.log", domainName)
+
+				// It can take a few seconds to the log file to be created
+				for {
+					_, err = os.Stat(logfile)
+					if !os.IsNotExist(err) {
+						break
+					}
+					time.Sleep(time.Second)
+				}
+
+				file, err := os.Open(logfile)
+				if err != nil {
+					log.Log.Reason(err).Error("failed to catch virtlogd logs")
+					return
+				}
+				defer file.Close()
+
+				scanner := bufio.NewScanner(file)
+				scanner.Buffer(make([]byte, 1024), 512*1024)
+				for scanner.Scan() {
+					log.LogQemuLogLine(log.Log, scanner.Text())
+				}
+
+				if err := scanner.Err(); err != nil {
+					log.Log.Reason(err).Error("failed to read virtlogd logs")
+				}
+			}()
+
 			go func() {
 				defer close(exitChan)
 				cmd.Wait()
@@ -256,11 +286,11 @@ func StartVirtlog(stopChan chan struct{}) {
 				cmd.Process.Kill()
 				return
 			case <-exitChan:
-				log.Log.Errorf("libvirtd exited, restarting")
+				log.Log.Errorf("virtlogd exited, restarting")
 			}
 
 			// this sleep is to avoid consumming all resources in the
-			// event of a libvirtd crash loop.
+			// event of a virtlogd crash loop.
 			time.Sleep(time.Second)
 		}
 	}()

pkg/virt-launcher/virtwrap/util/libvirt_helper_test.go

@@ -59,6 +59,61 @@ const (
 {"component":"test","level":"warning","msg":"Unable to open vhost-net. Opened so far 0, requested 1","pos":"qemuInterfaceOpenVhostNet:687","subcomponent":"libvirt","thread":"26","timestamp":"2018-10-04T09:20:44.177000Z"}
 {"component":"test","level":"error","msg":"At least one cgroup controller is required: No such device or address","pos":"virCgroupDetect:714","subcomponent":"libvirt","thread":"26","timestamp":"2018-10-04T09:20:44.284000Z"}
 {"component":"test","level":"error","msg":"At least one cgroup controller is required: No such device or address","pos":"virCgroupDetect:715","subcomponent":"libvirt","thread":"26","timestamp":"2018-10-04T13:39:13.905000Z"}`
+
+	qemuLogs = `2020-07-02 09:04:39.037+0000: starting up libvirt version: 6.0.0, package: 16.fc31 (Unknown, 2020-04-07-15:55:55, ), qemu version: 4.2.0qemu-kvm-4.2.0-15.fc31, kernel: 3.10.0-1062.9.1.el7.x86_64, hostname: vmi-alpine-efi
+LC_ALL=C \
+PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin \
+HOME=/var/lib/libvirt/qemu/domain-1-default_vmi-alpine-e \
+XDG_DATA_HOME=/var/lib/libvirt/qemu/domain-1-default_vmi-alpine-e/.local/share \
+XDG_CACHE_HOME=/var/lib/libvirt/qemu/domain-1-default_vmi-alpine-e/.cache \
+XDG_CONFIG_HOME=/var/lib/libvirt/qemu/domain-1-default_vmi-alpine-e/.config \
+QEMU_AUDIO_DRV=none \
+/usr/libexec/qemu-kvm \
+-name guest=default_vmi-alpine-efi,debug-threads=on \
+-S \
+-object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-1-default_vmi-alpine-e/master-key.aes \
+-blockdev '{"driver":"file","filename":"/usr/share/OVMF/OVMF_CODE.fd","node-name":"libvirt-pflash0-storage","auto-read-only":true,"discard":"unmap"}' \
+-blockdev '{"node-name":"libvirt-pflash0-format","read-only":true,"driver":"raw","file":"libvirt-pflash0-storage"}' \
+-blockdev '{"driver":"file","filename":"/tmp/default_vmi-alpine-efi","node-name":"libvirt-pflash1-storage","auto-read-only":true,"discard":"unmap"}' \
+-blockdev '{"node-name":"libvirt-pflash1-format","read-only":false,"driver":"raw","file":"libvirt-pflash1-storage"}' \
+-machine pc-q35-rhel8.2.0,accel=kvm,usb=off,dump-guest-core=off,pflash0=libvirt-pflash0-format,pflash1=libvirt-pflash1-format \
+-cpu Skylake-Client,ss=on,hypervisor=on,tsc-adjust=on,clflushopt=on,umip=on,arch-capabilities=on,pdpe1gb=on,skip-l1dfl-vmentry=on \
+-m 1024 \
+-overcommit mem-lock=off \
+-smp 1,sockets=1,dies=1,cores=1,threads=1 \
+-object iothread,id=iothread1 \
+-uuid 5c6fa8f7-c3f6-4b3f-b596-d16ea3912302 \
+-smbios type=1,manufacturer=KubeVirt,product=None,uuid=5c6fa8f7-c3f6-4b3f-b596-d16ea3912302,family=KubeVirt \
+-no-user-config \
+-nodefaults \
+-chardev socket,id=charmonitor,fd=20,server,nowait \
+-mon chardev=charmonitor,id=monitor,mode=control \
+-rtc base=utc \
+-no-shutdown \
+-boot strict=on \
+-device pcie-root-port,port=0x10,chassis=1,id=pci.1,bus=pcie.0,multifunction=on,addr=0x2 \
+-device pcie-root-port,port=0x11,chassis=2,id=pci.2,bus=pcie.0,addr=0x2.0x1 \
+-device pcie-root-port,port=0x12,chassis=3,id=pci.3,bus=pcie.0,addr=0x2.0x2 \
+-device pcie-root-port,port=0x13,chassis=4,id=pci.4,bus=pcie.0,addr=0x2.0x3 \
+-device virtio-serial-pci,id=virtio-serial0,bus=pci.2,addr=0x0 \
+-blockdev '{"driver":"file","filename":"/var/run/kubevirt/container-disks/disk_0.img","node-name":"libvirt-2-storage","cache":{"direct":true,"no-flush":false},"auto-read-only":true,"discard":"unmap"}' \
+-blockdev '{"node-name":"libvirt-2-format","read-only":true,"cache":{"direct":true,"no-flush":false},"driver":"raw","file":"libvirt-2-storage"}' \
+-blockdev '{"driver":"file","filename":"/var/run/kubevirt-ephemeral-disks/disk-data/containerdisk/disk.qcow2","node-name":"libvirt-1-storage","cache":{"direct":true,"no-flush":false},"auto-read-only":true,"discard":"unmap"}' \
+-blockdev '{"node-name":"libvirt-1-format","read-only":false,"cache":{"direct":true,"no-flush":false},"driver":"qcow2","file":"libvirt-1-storage","backing":"libvirt-2-format"}' \
+-device virtio-blk-pci,scsi=off,bus=pci.3,addr=0x0,drive=libvirt-1-format,id=ua-containerdisk,bootindex=1,write-cache=on \
+-netdev tap,fd=22,id=hostua-default,vhost=on,vhostfd=23 \
+-device virtio-net-pci,host_mtu=1450,netdev=hostua-default,id=ua-default,mac=22:f8:ef:32:60:95,bus=pci.1,addr=0x0 \
+-chardev socket,id=charserial0,fd=24,server,nowait \
+-device isa-serial,chardev=charserial0,id=serial0 \
+-chardev socket,id=charchannel0,fd=25,server,nowait \
+-device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_agent.0 \
+-vnc vnc=unix:/var/run/kubevirt-private/6d220540-cae6-4aa3-a850-af62ff66e407/virt-vnc \
+-device VGA,id=video0,vgamem_mb=16,bus=pcie.0,addr=0x1 \
+-sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny \
+-msg timestamp=on`
+
+	qemuFormattedLogs = `{"component":"virt-launcher","level":"info","msg":"2020-07-02 09:04:39.037+0000: starting up libvirt version: 6.0.0, package: 16.fc31 (Unknown, 2020-04-07-15:55:55, ), qemu version: 4.2.0qemu-kvm-4.2.0-15.fc31, kernel: 3.10.0-1062.9.1.el7.x86_64, hostname: vmi-alpine-efi","subcomponent":"qemu","timestamp":"2020-07-02T09:04:39.303235Z"}
+{"component":"virt-launcher","level":"info","msg":"LC_ALL=C \\PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin \\HOME=/var/lib/libvirt/qemu/domain-1-default_vmi-alpine-e \\XDG_DATA_HOME=/var/lib/libvirt/qemu/domain-1-default_vmi-alpine-e/.local/share \\XDG_CACHE_HOME=/var/lib/libvirt/qemu/domain-1-default_vmi-alpine-e/.cache \\XDG_CONFIG_HOME=/var/lib/libvirt/qemu/domain-1-default_vmi-alpine-e/.config \\QEMU_AUDIO_DRV=none \\/usr/libexec/qemu-kvm \\-name guest=default_vmi-alpine-efi,debug-threads=on \\-S \\-object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-1-default_vmi-alpine-e/master-key.aes \\-blockdev '{\"driver\":\"file\",\"filename\":\"/usr/share/OVMF/OVMF_CODE.fd\",\"node-name\":\"libvirt-pflash0-storage\",\"auto-read-only\":true,\"discard\":\"unmap\"}' \\-blockdev '{\"node-name\":\"libvirt-pflash0-format\",\"read-only\":true,\"driver\":\"raw\",\"file\":\"libvirt-pflash0-storage\"}' \\-blockdev '{\"driver\":\"file\",\"filename\":\"/tmp/default_vmi-alpine-efi\",\"node-name\":\"libvirt-pflash1-storage\",\"auto-read-only\":true,\"discard\":\"unmap\"}' \\-blockdev '{\"node-name\":\"libvirt-pflash1-format\",\"read-only\":false,\"driver\":\"raw\",\"file\":\"libvirt-pflash1-storage\"}' \\-machine pc-q35-rhel8.2.0,accel=kvm,usb=off,dump-guest-core=off,pflash0=libvirt-pflash0-format,pflash1=libvirt-pflash1-format \\-cpu Skylake-Client,ss=on,hypervisor=on,tsc-adjust=on,clflushopt=on,umip=on,arch-capabilities=on,pdpe1gb=on,skip-l1dfl-vmentry=on \\-m 1024 \\-overcommit mem-lock=off \\-smp 1,sockets=1,dies=1,cores=1,threads=1 \\-object iothread,id=iothread1 \\-uuid 5c6fa8f7-c3f6-4b3f-b596-d16ea3912302 \\-smbios type=1,manufacturer=KubeVirt,product=None,uuid=5c6fa8f7-c3f6-4b3f-b596-d16ea3912302,family=KubeVirt \\-no-user-config \\-nodefaults \\-chardev socket,id=charmonitor,fd=20,server,nowait \\-mon chardev=charmonitor,id=monitor,mode=control \\-rtc base=utc \\-no-shutdown \\-boot strict=on \\-device pcie-root-port,port=0x10,chassis=1,id=pci.1,bus=pcie.0,multifunction=on,addr=0x2 \\-device pcie-root-port,port=0x11,chassis=2,id=pci.2,bus=pcie.0,addr=0x2.0x1 \\-device pcie-root-port,port=0x12,chassis=3,id=pci.3,bus=pcie.0,addr=0x2.0x2 \\-device pcie-root-port,port=0x13,chassis=4,id=pci.4,bus=pcie.0,addr=0x2.0x3 \\-device virtio-serial-pci,id=virtio-serial0,bus=pci.2,addr=0x0 \\-blockdev '{\"driver\":\"file\",\"filename\":\"/var/run/kubevirt/container-disks/disk_0.img\",\"node-name\":\"libvirt-2-storage\",\"cache\":{\"direct\":true,\"no-flush\":false},\"auto-read-only\":true,\"discard\":\"unmap\"}' \\-blockdev '{\"node-name\":\"libvirt-2-format\",\"read-only\":true,\"cache\":{\"direct\":true,\"no-flush\":false},\"driver\":\"raw\",\"file\":\"libvirt-2-storage\"}' \\-blockdev '{\"driver\":\"file\",\"filename\":\"/var/run/kubevirt-ephemeral-disks/disk-data/containerdisk/disk.qcow2\",\"node-name\":\"libvirt-1-storage\",\"cache\":{\"direct\":true,\"no-flush\":false},\"auto-read-only\":true,\"discard\":\"unmap\"}' \\-blockdev '{\"node-name\":\"libvirt-1-format\",\"read-only\":false,\"cache\":{\"direct\":true,\"no-flush\":false},\"driver\":\"qcow2\",\"file\":\"libvirt-1-storage\",\"backing\":\"libvirt-2-format\"}' \\-device virtio-blk-pci,scsi=off,bus=pci.3,addr=0x0,drive=libvirt-1-format,id=ua-containerdisk,bootindex=1,write-cache=on \\-netdev tap,fd=22,id=hostua-default,vhost=on,vhostfd=23 \\-device virtio-net-pci,host_mtu=1450,netdev=hostua-default,id=ua-default,mac=22:f8:ef:32:60:95,bus=pci.1,addr=0x0 \\-chardev socket,id=charserial0,fd=24,server,nowait \\-device isa-serial,chardev=charserial0,id=serial0 \\-chardev socket,id=charchannel0,fd=25,server,nowait \\-device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_agent.0 \\-vnc vnc=unix:/var/run/kubevirt-private/6d220540-cae6-4aa3-a850-af62ff66e407/virt-vnc \\-device VGA,id=video0,vgamem_mb=16,bus=pcie.0,addr=0x1 \\-sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny \\-msg timestamp=on","subcomponent":"qemu","timestamp":"2020-07-02T09:04:39.303348Z"}`
 )
 
 var _ = Describe("LibvirtHelper", func() {
@@ -101,4 +156,43 @@ var _ = Describe("LibvirtHelper", func() {
 
 		Expect(loggedLines).To(Equal(expectedLines))
 	})
+
+	It("should parse qemu logs", func() {
+		buffer := bytes.NewBuffer(nil)
+
+		kubevirtlog.InitializeLogging("virt-launcher")
+		logger := log.NewContext(log.NewJSONLogger(buffer))
+		klog := kubevirtlog.MakeLogger(logger)
+
+		scanner := bufio.NewScanner(strings.NewReader(qemuLogs))
+		for scanner.Scan() {
+			kubevirtlog.LogQemuLogLine(klog, scanner.Text())
+		}
+
+		scanner = bufio.NewScanner(buffer)
+
+		loggedLines := []map[string]string{}
+
+		for scanner.Scan() {
+			entry := map[string]string{}
+			err := json.Unmarshal(scanner.Bytes(), &entry)
+			Expect(err).To(Not(HaveOccurred()))
+			delete(entry, "timestamp")
+			loggedLines = append(loggedLines, entry)
+		}
+		Expect(scanner.Err()).To(Not(HaveOccurred()))
+
+		expectedLines := []map[string]string{}
+		scanner = bufio.NewScanner(strings.NewReader(qemuFormattedLogs))
+		for scanner.Scan() {
+			entry := map[string]string{}
+			err := json.Unmarshal(scanner.Bytes(), &entry)
+			Expect(err).To(Not(HaveOccurred()))
+			delete(entry, "timestamp")
+			expectedLines = append(expectedLines, entry)
+		}
+		Expect(scanner.Err()).To(Not(HaveOccurred()))
+
+		Expect(loggedLines).To(Equal(expectedLines))
+	})
 })

staging/src/kubevirt.io/client-go/log/log.go

@@ -403,3 +403,32 @@ func LogLibvirtLogLine(logger *FilteredLogger, line string) {
 		)
 	}
 }
+
+var qemuLogLines = ""
+
+func LogQemuLogLine(logger *FilteredLogger, line string) {
+
+	if len(strings.TrimSpace(line)) == 0 {
+		return
+	}
+
+	// Concat break lines to have full command in one log message
+	if strings.HasSuffix(line, "\\") {
+		qemuLogLines += line
+		return
+	}
+
+	if len(qemuLogLines) > 0 {
+		line = qemuLogLines + line
+		qemuLogLines = ""
+	}
+
+	now := time.Now()
+	logger.logContext.Log(
+		"level", "info",
+		"timestamp", now.Format("2006-01-02T15:04:05.000000Z"),
+		"component", logger.component,
+		"subcomponent", "qemu",
+		"msg", line,
+	)
+}