Bug 1720975

Likely 4.5, but no milestone yet

Actually, I wouldn’t do that at all. Starting VM is the critical part of VM lifecycle, we need detailed information on what we sent(not always engine.log is available), how it was modified by hooks(since we do not have control what has been deployed/modified) and what was the resulting VM after processed by libvirt and qemu. Each of the three has its purpose. Now repeated dumpxml signalizes that devices has changed(happens on startup, e.g. agent becomes responsive) and again that is the only place where we can see how reporting changed. We do not log runtime stats

You could highlight just the diff, but that’s imho not worth the effort

Hi Michal,

I get your point that we need the XML before and after hooks, I agree with it. But please see below

(In reply to Michal Skrivanek from comment #2)
> Actually, I wouldn’t do that at all. Starting VM is the critical part of VM
> lifecycle, we need detailed information on what we sent(not always
> engine.log is available),

Yes, it critical. But unless something is wrong, engine logs rotate much slower than vdsm so we should have engine xml before hooks in engine.log

> control what has been deployed/modified) and what was the resulting VM after
> processed by libvirt and qemu. Each of the three has its purpose. Now
> repeated dumpxml signalizes that devices has changed(happens on startup,
> e.g. agent becomes responsive) and again that is the only place where we can
> see how reporting changed. We do not log runtime stats

Also keep in mind, we already have running XML due to the virsh plugin in sosreport.

> You could highlight just the diff, but that’s imho not worth the effort
Agree

I don't recall having problems (or opening bugs) with this part, I think its quite stable and good so I'm not sure its necessary to keep all these XML dumps with INFO level (except post hooks), perhaps DEBUG is enough and it can be enabled if necessary?

Also, dumpxml is logged on engine side too, with INFO level, we have a lot of duplicated data on INFO level.

2019-06-19 11:48:09,911+10 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DumpXmlsVDSCommand] (ForkJoinPool-1-worker-14) [] FINISH, DumpXmlsVDSCommand, return: {177aef33-ec53-4e3e-a437-955186a08aef=<domain type='kvm' id='12' xmlns:qemu='http://libvirt.org/schemas/domain/qemu/1.0'>
  <name>rhel7-test1</name>
  <uuid>177aef33-ec53-4e3e-a437-955186a08aef</uuid>
  <metadata xmlns:ns0="http://ovirt.org/vm/tune/1.0" xmlns:ovirt-vm="http://ovirt.org/vm/1.0">
    <ns0:qos/>
    <ovirt-vm:vm xmlns:ovirt-vm="http://ovirt.org/vm/1.0">
    <ovirt-vm:clusterVersion>4.3</ovirt-vm:clusterVersion>
    <ovirt-vm:destroy_on_reboot type="bool">False</ovirt-vm:destroy_on_reboot>
    <ovirt-vm:launchPaused>false</ovirt-vm:launchPaused>
    <ovirt-vm:memGuaranteedSize type="int">2048</ovirt-vm:memGuaranteedSize>
    <ovirt-vm:minGuaranteedMemoryMb type="int">2048</ovirt-vm:minGuaranteedMemoryMb>
    <ovirt-vm:resumeBehavior>auto_resume</ovirt-vm:resumeBehavior>
    <ovirt-vm:startTime type="float">1560908915.17</ovirt-vm:startTime>
    <ovirt-vm:device mac_address="56:6f:5d:1c:00:00">

Granted, but it isn't always going to be immediately clear why a VM failed to start.

Imagine that a hook is enabled on the host. Engine XML looks ok, but the VM fails to start, and is destroyed, so it's not always available in virsh. Users would need to change the log level (and know that they need to do it), re-schedule the VM, then create a new sosreport with the modified XML in vdsm.log

Is it worth the additional effort to support to remove the lines from the logs?

Ryan,

I want to keep the post hook XML in vdsm logs. I'm suggesting to remove the pre-hook XML (vm create api) and dumpxml as both are one engine logs.

So we should know why the VM failed to start, or at least have the XML that failed in case the error is not clear (most of the time its enough).

I still favor keeping both because we often don't really get logs from both sides. It really shouldn't hurt as it's not periodic. Maybe we can just print the post-hook xml only when it's actually different? That would be one xml less without much effort...

(In reply to Michal Skrivanek from comment #6)
> I still favor keeping both because we often don't really get logs from both
> sides. It really shouldn't hurt as it's not periodic. Maybe we can just
> print the post-hook xml only when it's actually different? That would be one
> xml less without much effort...

Well, we do get logs from both sides almost always, and engine rotates much slower than VDSM, so anything that is on engine does not really need to be on vdsm logs.
It hurts on bigger environments, with VM Pools etc.
Printing just when its different would be a step forward, these XMLs are quite a few lines.

Up to you to decide, this was just a suggestion to reduce noise.

(In reply to Michal Skrivanek from comment #6)
> Maybe we can just
> print the post-hook xml only when it's actually different? That would be one
> xml less without much effort...

+1

I can understand the log is quite verbose but it's actually not so easy to prune it. I agree with Michal that it's good to have the domain XMLs in Vdsm logs and not to rely only on Engine logs. We have the following domain XML occurrences in the Vdsm logs:

- The argument of the VM.create call. I think we don't want to mess with selectively suppressing API call arguments (the current handling of secrets is messy enough).
- The return value of the VM.create call. Maybe this could be omitted but it can be still useful.
- The one after applying the hooks. This is the only one nicely formatted and easily readable -- I like it.
- The Host.dumpxmls return value. This may be redundant too, but again, it's good to see what and when exactly is reported to Engine without correlating multiple logs. My experience about suppressing most of the VM stats return values is not particularly good, such information is often missing.

I initially thought that this could be easy and quick to improve but after looking into the logs, it's not that obvious. Considering the above, Comment 11 and the other comments, I think it's best to keep it as it is and focus on other bugs, so closing.