Bug 1314826

Summary: No debug log entry for user executing an action or query
Product: [oVirt] ovirt-engine Reporter: Ravi Nori <rnori>
Component: Backend.CoreAssignee: Ravi Nori <rnori>
Status: CLOSED CURRENTRELEASE QA Contact: Petr Matyáš <pmatyas>
Severity: low Docs Contact:
Priority: low    
Version: 4.0.0CC: bugs, gklein, mgoldboi, mperina, oourfali, pkubica, rnori, sbonazzo, tnisan
Target Milestone: ovirt-3.6.7Flags: rule-engine: ovirt-3.6.z+
mgoldboi: planning_ack+
mperina: devel_ack+
pstehlik: testing_ack+
Target Release: 3.6.7   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-07-04 12:32:45 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Infra RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
engine log none

Description Ravi Nori 2016-03-04 16:00:10 UTC 
Description of problem:

There is no debug information in the engine.log to indicate which user is executing a query or action.

Version-Release number of selected component (if applicable): 4.0


How reproducible:
Enable debug log level and start engine

Steps to Reproduce:
1. Execute a query or action

Actual results:
engine.log does not have debug log on which query/action is executed by user

Expected results:
There should be an entry in engine.log indicating that a query/action is being executed by a user
Comment 1 Petr Kubica 2016-04-15 13:52:24 UTC 
Hi,
when I removed a VM, I cannot find in log which user did it.
for example:

2016-04-15 15:39:47,224 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-5) [37107067] Correlation ID: 53754440, Job ID: 6ddf0b06-cc2d-44af-9a1b-223ab9acac66, Call Stack: null, Custom Event ID: -1, Message: VM foofoo was created by admin@internal.
....
2016-04-15 15:40:29,841 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-37) [45d2fb2c] Correlation ID: 45d2fb2c, Job ID: f90bdc36-049d-459d-8013-d65e87afc507, Call Stack: null, Custom Event ID: -1, Message: VM foofoo was successfully removed.

-> missing "by admin@internal"
Comment 2 Red Hat Bugzilla Rules Engine 2016-04-18 10:31:16 UTC 
Target release should be placed once a package build is known to fix a issue. Since this bug is not modified, the target version has been reset. Please use target milestone to plan a fix for a oVirt release.
Comment 3 Ravi Nori 2016-04-19 17:42:41 UTC 
Its a debug log entry please test with debug enabled
Comment 4 Oved Ourfali 2016-05-04 06:27:47 UTC 
Moving to ON_QA until we get feedback from Petr.
Comment 5 Petr Matyáš 2016-05-11 15:19:08 UTC 
Created attachment 1156204 [details]
engine log

After some archaeology work, I didn't find any message in DEBUG related to missing user which deleted a VM. If you want, you can check yourself. I can provide access to a working engine with debug log level which you can use.
Comment 6 Red Hat Bugzilla Rules Engine 2016-05-11 15:19:37 UTC 
Target release should be placed once a package build is known to fix a issue. Since this bug is not modified, the target version has been reset. Please use target milestone to plan a fix for a oVirt release.
Comment 7 Petr Matyáš 2016-05-11 15:20:44 UTC 
Sorry, I forgot to mention I'am using 3.6.6-3
Comment 8 Red Hat Bugzilla Rules Engine 2016-05-11 15:20:50 UTC 
Target release should be placed once a package build is known to fix a issue. Since this bug is not modified, the target version has been reset. Please use target milestone to plan a fix for a oVirt release.
Comment 9 Martin Perina 2016-05-12 08:23:53 UTC 
Just verified that everything works fine on 3.6.6, IMO the issue during verifying the bug is caused by a bit tricky logging configuration. In order to see those debug messages following category has to be enable in ovirt-engine.xml.in:

 <logger category="org.ovirt.engine.core.bll">                                 
   <level name="DEBUG"/>                                 
 </logger>                                          

Using the above you can see debug logs for both commands and queries, for example:

 2016-05-12 10:09:19,442 DEBUG [org.ovirt.engine.core.bll.Backend] (default task-32) [] Executing command AddEmptyStoragePool for user admin@internal-authz.

 2016-05-12 10:09:22,406 DEBUG [org.ovirt.engine.core.bll.Backend] (default task-54) [] Executing query GetConnectionsByDataCenterAndStorageType with isFiltered : false for user admin@internal-authz.
 

Maybe a bit confusing is, that DEBUG logging can be turned on/off for each package (category) and we have following default in ovirt-engine.xml.in:

 <logger category="org.ovirt" use-parent-handlers="false">
   <level name="INFO"/>
   ...
 </logger>

 ...

 <logger category="org.ovirt.engine.core.bll">
   <level name="INFO"/>
 </logger>

So if you change log level to DEBUG for category "org.ovirt", then for category "org.ovirt.engine.core.bll" it's overwritten to INFO. And to show debug logs described in the bug description, we need to have set DEBUG on category "org.ovirt.engine.core.bll" at minimum.

I will try to reach Petr today, check his setup ...
Comment 10 Petr Matyáš 2016-05-12 09:01:05 UTC 
Add VM command is logged, but Remove VM command isn't.
Comment 11 Petr Matyáš 2016-05-26 14:38:40 UTC 
Verified on 3.6.7-1

All actions I checked had findable user id in debug log