Logging of QEMU command line and QMP

[foxtrotcz]

Hi,
as written here, the QMP is currently very opaque and you plan to move away from config file and use only QEMU command line and QMP.
I thought that for debugging purposes it would be nice if QEMU command line and QMP commands/responses were logged so people can see what exactly is configured.

1. For QEMU command line, specifically the init command I think it would be enough to setup logging here.
   

   incus/internal/server/instance/drivers/driver_qemu.go

   Line 1704 in 58bdbb5

   p, err := subprocess.NewProcess(d.state.OS.ExecPath, append(forkLimitsCmd, qemuCmd...), d.EarlyLogFilePath(), d.EarlyLogFilePath())

   
   Either just the qemuCmd or the whole thing with p variable.

2. For QMP that would mean logging request and out variables and filtering them by m.path.
   

   incus/internal/server/instance/drivers/qmp/monitor.go

   Line 188 in 58bdbb5

   out, err := m.qmp.Run(request)

   
   Then I think saving as file in appropriate folder in /var/log/incus/ would be best.

When I tried modifying my self-compiled Incus, print was enough for me, because I am not capable making robust solution.

out, err := m.qmp.Run(request)
fmt.Println(m.path)
fmt.Println(string(request))
fmt.Println(string(out))

3. Variable resp also seems to have some useful info.
   

   incus/internal/server/instance/drivers/qmp/monitor.go

   Line 182 in 58bdbb5

   func (m *Monitor) RunJSON(request []byte, resp any) error {

   
   A lot is empty but when printed I also got this when starting stock Windows VM install.
   
   So this could also be logged to file.
   Edit: Actually not needed, included in QMP output Logging of QEMU command line and QMP  #1240 (comment)

Currently I have to compile my own Incus and add print statements to get to these commands and logs. I think if this was all logged in files inside /var/log/incus/ that would be great for debugging.
Thanks for consideration.

[stgraber]

Yeah, we could certainly write more info into /run/incus/NAME/qemu.log or similar.

What we need to be careful with though is that user action inside the guest should not be able to grow that log. Otherwise we're risking a denial of service type attack from the guest.

So we definitely don't want to log all the QMP events as some of those are guest-triggered.
But logging the initial QEMU command line and then log the QMP commands we send out should be fine.
I probably wouldn't log the response to those commands though as that's where it may pull in guest information and cause the log to grow out of control.

[foxtrotcz]

I thought that the log file could have size limit and delete oldest entries so it doesn't grow indefinitely.
This can be important because Incus keeps sending {"execute":"ringbuf-read","arguments":{"device":"qemu_serial-chardev","format":"utf8","size":16}} even if nothing is happening and this will grow the log file.

About responses I understand. They are empty most of the time anyway.
At the start Incus does query of cpu like query-hotpluggable-cpus , query-cpu-model-expansion and query-hotpluggable-cpus so it then returns some information but I dont know how important that would be for debugging purposes.

I also found out that output from variable resp in part 3. is actually included in QMP output when executing "execute":"ringbuf-read" so there is no need to log it separately.

But the most important to log are the QEMU init command and Incus QMP commands.
QMP output only if there is some good solution so its not dangerous like you said.

[stgraber]

Ah yeah, we probably wouldn't want to send the ringbuf-read ones as that doesn't really do anything to the VM config anyways.

Making the file on disk be effectively a ringbuffer (trim old stuff as you write new entries) is a bit tricky because of having to deal with concurrent access/writes, I'd rather not have to deal with that by just limiting the amount of stuff written.

[bensmrs]

Hi! I see the issue has no assignee; if nobody is working on it, I can give it a shot

[bensmrs]

Yeah, we could certainly write more info into /run/incus/NAME/qemu.log or similar.

I’m not sure writing to the same file as QEMU is completely safe. OTOH having a third QEMU log file seems confusing. What do you suggest?

I probably wouldn't log the response to those commands though as that's where it may pull in guest information and cause the log to grow out of control.

If we’re only considering the commands used before POST, logging their responses looks fine to me.

But not everyone would be interested in these logs, so do we want to introduce yet another™ configuration key to specify the file in which we should log that? What would be the key name? Where would the file be? If it’s in /var/log/incus/{instance} by default, what about absolute paths, relative path traversal, and related AppArmor rules? If we’re logging responses, how would the file be formatted to disambiguate between requests and responses?

I need to clarify these points before writing any code.

[stgraber]

So I think we can do qemu.qmp.log.

As for its content, I think we should only log the commands we send out and the response we're getting back rather than log all QMP traffic. This will avoid us growing the log purely as a response to guest activity. We also need to filter some of our own commands, specifically the ringbuf stuff as that would otherwise grow the file in an unsustainable way.

[bensmrs]

Alright, so qemu.qmp.log then.
We’ll log everything (not only before POST). It’ll just be a simple modification of the Run function then, ignoring ringbuf-read (and other functions to be determined).
Regarding the format, because everything is JSON, would a “stacked” JSON file (that we’d rather call qemu.qmp.json then?) consisting of {"timestamp": …, "request": …, "response": …} lines be good?
Or a more “log-like” format like the following?

[{timestamp}] {json request}
{json response}
{new line}

[stgraber]

I suspect something more log-ish will be better, possibly something like:

[TIMESTAMP] QUERY: XYZ
[TIMESTAMP] REPLY: XYZ
BLANK

So same prefix length for both requests and reply so it's easy to read through with blank line between entries, that should make it easy to grep/parse and to visually follow.

[bensmrs]

Yeah, about that…
Because almost everything is JSON, do we log the whole queries and replies? The whole queries and only the .response part of the reply? And I guess on single lines?
Sorry for all these boring questions, but I feel like the goal of readability is a daring one: if we want something really readable, we’ll have to pretty-print some JSON, but then parsing it would be hell; OTOH, if we want something easily parsable, then the JSONs will have to be on single lines, thus making it pretty hard for humans.

We may have two contradictory goals at play here… What exactly are the XYZ?

[stgraber]

I'd likely keep request and response as JSON and on one line. It's not the easiest to read but also not too terrible and it makes it easy to parse/extract and dump into jq.

I'd probably do something like grep QUERY.*query-cpu /var/log/incus/v1/qemu.qmp.log -A1 | grep RESP | tail | cut -d' ' -f3- | jq

[bensmrs]

Okay then, I think I have everything I need :)

[foxtrotcz]

Thanks for your work @bensmrs
Will you setup just QMP logging or also the init QEMU command?

[bensmrs]

Oh I forgot about that… @stgraber, would EarlyLogFilePath() be a good place to store the QEMU command line?
Edit: it’s truncated by NewProcess, and messing with it is probably not such a good idea; Should a new file be used, or just logging to the Incus logging facility would be enough?

[stgraber]

Hmm, I actually don't think we need to actively log that. If QEMU starts properly, then you will see the command line in the process most, if it fails to start, we already show it in the error message.

If it was easy to add to early.log, I wouldn't be opposed to duplicating it there, but as you said, that's not exactly easy as the subprocess package clears it.

[bensmrs]

I was considering adding it as a Debug entry to the logger. It’s 2 lines of code, I’ll let you accept or reject the PR.