Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1224285

Summary:	[AAA] reduce or remove logout fail log/event message "null@N/A"
Product:	[Retired] oVirt	Reporter:	Jiri Belka <jbelka>
Component:	ovirt-engine-core	Assignee:	Ravi Nori <rnori>
Status:	CLOSED WORKSFORME	QA Contact:	Ondra Machacek <omachace>
Severity:	low	Docs Contact:
Priority:	unspecified
Version:	3.5	CC:	alonbl, bugs, ecohen, gklein, jbelka, lpeer, lsurette, oourfali, rbalakri, Rhev-m-bugs, yeylon
Target Milestone:	---
Target Release:	3.6.0
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:	infra
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2015-08-03 13:59:42 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:
Bug Depends On:
Bug Blocks:	1198493

Description Jiri Belka 2015-05-22 12:51:44 UTC

Description of problem:

It seems LogoutUserCommand which is used to invalidate session is run multiple times and this causes ERROR level messages. ERROR level messages should be seen only for real problems which would need admin intervention. If this is just internal then it should not be ERROR level.

Maybe this multiplication of LogoutUserCommand also causes odd events - Message: Failed to log User null@N/A out.

2015-05-22 14:40:42,717 TRACE [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-9) START, ValidateSessionQuery(refresh: false, filtered: false), log id: 2cb43d10
2015-05-22 14:40:42,717 DEBUG [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-9) Calling ValidateSession
2015-05-22 14:40:42,718 DEBUG [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-9) Input session ID is: GMM9cRyfwSpILZ9jEFmkWCuJ81AYkltLsQ43Hehg1XmX3f5Bsad8rznolJV3vgm5UkSk3puBEQA4ebZGVaNoLQ==
2015-05-22 14:40:42,718 DEBUG [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-9) Didn't find session user
2015-05-22 14:40:42,718 DEBUG [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-9) ValidateSession ended
2015-05-22 14:40:42,718 TRACE [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-9) FINISH, ValidateSessionQuery, log id: 2cb43d10
2015-05-22 14:40:42,817 INFO  [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-1) [589f634d] Running command: LogoutUserCommand(UserId = fdfc627c-d875-11e0-90f0-83df133b58cc) internal: false.
2015-05-22 14:40:42,837 INFO  [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-4) [293c9159] Running command: LogoutUserCommand(UserId = fdfc627c-d875-11e0-90f0-83df133b58cc) internal: false.
2015-05-22 14:40:42,839 DEBUG [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-4) [293c9159] Command [id=eed6ae22-3391-445b-bd44-c7bc79da83ef]: No compensation data.
2015-05-22 14:40:42,832 INFO  [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-5) [d352ca4] Running command: LogoutUserCommand(UserId = fdfc627c-d875-11e0-90f0-83df133b58cc) internal: false.
2015-05-22 14:40:42,851 INFO  [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-6) [7c0c41e2] Running command: LogoutUserCommand(UserId = fdfc627c-d875-11e0-90f0-83df133b58cc) internal: false.
2015-05-22 14:40:42,855 DEBUG [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-1) [589f634d] Command [id=a24eaf31-d925-4413-8c75-8495fa995608]: No compensation data.
2015-05-22 14:40:42,855 DEBUG [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-6) [7c0c41e2] Command [id=e114c9d0-1ce0-4b15-9331-43caa6c28dce]: No compensation data.
2015-05-22 14:40:42,858 ERROR [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-4) [293c9159] Transaction rolled-back for command: org.ovirt.engine.core.bll.aaa.LogoutUserCommand.
2015-05-22 14:40:42,865 ERROR [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-1) [589f634d] Transaction rolled-back for command: org.ovirt.engine.core.bll.aaa.LogoutUserCommand.
2015-05-22 14:40:42,867 ERROR [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-6) [7c0c41e2] Transaction rolled-back for command: org.ovirt.engine.core.bll.aaa.LogoutUserCommand.
2015-05-22 14:40:42,871 INFO  [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-8) [7aa4e168] Running command: LogoutUserCommand(UserId = fdfc627c-d875-11e0-90f0-83df133b58cc) internal: false.
2015-05-22 14:40:42,876 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-6) [7c0c41e2] Correlation ID: 7c0c41e2, Call Stack: null, Custom Event ID: -1, Message: Failed to log User null@N/A out.
2015-05-22 14:40:42,878 DEBUG [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-8) [7aa4e168] Command [id=3f9bc673-a7b6-49b3-a83a-101c270be900]: No compensation data.
2015-05-22 14:40:42,879 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-1) [589f634d] Correlation ID: 589f634d, Call Stack: null, Custom Event ID: -1, Message: Failed to log User null@N/A out.
2015-05-22 14:40:42,881 ERROR [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-8) [7aa4e168] Transaction rolled-back for command: org.ovirt.engine.core.bll.aaa.LogoutUserCommand.
2015-05-22 14:40:42,883 DEBUG [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-5) [d352ca4] Command [id=4e9fc90c-0214-4746-a36e-32aeb0442a8a]: No compensation data.
2015-05-22 14:40:42,892 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-4) [293c9159] Correlation ID: 293c9159, Call Stack: null, Custom Event ID: -1, Message: Failed to log User null@N/A out.
2015-05-22 14:40:42,903 DEBUG [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (DefaultQuartzScheduler_Worker-98) Before acquiring lock EngineLock [exclusiveLocks= key: 29f10533-99c5-44f7-a18a-5fc20d1d1b1f value: VDS_INIT
, sharedLocks= ]
2015-05-22 14:40:42,903 DEBUG [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (DefaultQuartzScheduler_Worker-98) Successed acquiring lock EngineLock [exclusiveLocks= key: 29f10533-99c5-44f7-a18a-5fc20d1d1b1f value: VDS_INIT
, sharedLocks= ] succeeded
2015-05-22 14:40:42,910 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-8) [7aa4e168] Correlation ID: 7aa4e168, Call Stack: null, Custom Event ID: -1, Message: Failed to log User null@N/A out.
2015-05-22 14:40:42,914 ERROR [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp-/127.0.0.1:8702-5) [d352ca4] Transaction rolled-back for command: org.ovirt.engine.core.bll.aaa.LogoutUserCommand.
2015-05-22 14:40:42,925 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-5) [d352ca4] Correlation ID: d352ca4, Call Stack: null, Custom Event ID: -1, Message: Failed to log User null@N/A out.


Version-Release number of selected component (if applicable):
rhevm-backend-3.5.3-0.2.el6ev.noarch

How reproducible:
100%

Steps to Reproduce:
1. have following values in vdc_options:

 UserSessionTimeOutInterval         | 10
 UserSessionHardLimit               | 5

2. login into Admin Portal as admin@internal
3. wait 5 mins to be logged out by hardlimit timeout

Actual results:
multiple ERROR level messages in engine.log and odd event about 'null@N/A.

Expected results:
at least no ERROR as logout was successful and odd 'null@N/A' should not be seen.

Additional info:

Comment 1 Alon Bar-Lev 2015-05-25 06:07:26 UTC

this is a dup of bug#1198493 but as I moved it to upstream (as it should) we leave it as-is.

Comment 2 Ravi Nori 2015-07-27 15:28:42 UTC

I can no longer reproduce this on current master, please test again.

Comment 3 Ravi Nori 2015-07-28 14:03:44 UTC

Was able to reprocude after fixing BZ 1227713

Comment 4 Ravi Nori 2015-08-03 13:59:42 UTC

After recent changes in LogoutSessionCommand the logout command is no longer executed on user session timeout. So scenario in this BZ does not coccur anymore.