Skip to content

Commit

Permalink
Export qemu logs as structured logs
Browse files Browse the repository at this point in the history 
QEMU logs are handled by virtlogd which defaults to creating a file to
store the logs. Those logs are not that verbose but it might help in
case of unexpected crashes.

Signed-off-by: Victor Toso <victortoso@redhat.com>
  • Loading branch information
@victortoso
victortoso committed Jul 2, 2020
1 parent 9b12bde commit 9e66e80
Show file tree
Hide file tree
Showing 4 changed files with 157 additions and 5 deletions.
7 changes: 3 additions & 4 deletions cmd/virt-launcher/virt-launcher.go
View file
Expand Up @@ -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()
Expand All @@ -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
Expand Down
32 changes: 31 additions & 1 deletion pkg/virt-launcher/virtwrap/util/libvirt_helper.go
View file
Expand Up @@ -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
Expand All @@ -246,6 +246,36 @@ func StartVirtlog(stopChan chan struct{}) {
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()
Expand Down
94 changes: 94 additions & 0 deletions pkg/virt-launcher/virtwrap/util/libvirt_helper_test.go
View file
Expand Up @@ -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() {
Expand Down Expand Up @@ -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))
})
})
29 changes: 29 additions & 0 deletions staging/src/kubevirt.io/client-go/log/log.go
View file
Expand Up @@ -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,
)
}

0 comments on commit 9e66e80

Please sign in to comment.