Bug 1025402

Summary:	log spam when handling async tasks
Product:	[Retired] oVirt	Reporter:	Allon Mureinik <amureini>
Component:	ovirt-engine-core	Assignee:	Ravi Nori <rnori>
Status:	CLOSED CURRENTRELEASE	QA Contact:	bugs <bugs>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	3.3	CC:	acathrow, bazulay, emesika, gshereme, iheim, laravot, pstehlik, yeylon
Target Milestone:	---	Keywords:	Triaged
Target Release:	3.5.0
Hardware:	x86_64
OS:	Linux
Whiteboard:	infra
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2014-04-30 15:43: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:

Description Allon Mureinik 2013-10-31 15:28:43 UTC

Description of problem:
Async tasks cause lots "spam" in the log file, includes errornous listing of org.ovirt.thread in class names (see below)



Version-Release number of selected component (if applicable):
Tested with upstream master, commit hash fbee8fe0a55dfe800b5e447eb094ed02ea83d750.

How reproducible:
100%

Steps to Reproduce:
Anything that involves async tasks - e.g.:
1. Create a VM
2. Take a (cold) snapshot
3. Merged the snapshot

Actual results:
Log is full of spam:
2013-10-31 16:39:27,692 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.pool-6-thread-18) SPMAsyncTask::ClearAsyncTask: Attempting to clear task 9ebd6916-4ba7-4f9d-afde-0032d4e62e99
2013-10-31 16:39:27,693 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.pool-6-thread-18) START, SPMClearTaskVDSCommand( storagePoolId = 5849b030-626e-47cb-ad90-3ce782d831b3, ignoreFailoverLimit = false, taskId = 9ebd6916-4ba7-4f9d-afde-0032d4e62e99), log id: 35537a08
2013-10-31 16:39:27,695 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.pool-6-thread-18) START, HSMClearTaskVDSCommand(HostName = h, HostId = e6ad8c25-3a8d-4ce7-9809-974151e413d9, taskId=9ebd6916-4ba7-4f9d-afde-0032d4e62e99), log id: 7b70be91
2013-10-31 16:39:27,773 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.pool-6-thread-18) FINISH, HSMClearTaskVDSCommand, log id: 7b70be91
2013-10-31 16:39:27,774 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.pool-6-thread-18) FINISH, SPMClearTaskVDSCommand, log id: 35537a08
2013-10-31 16:39:27,789 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.pool-6-thread-18) BaseAsyncTask::RemoveTaskFromDB: Removed task 9ebd6916-4ba7-4f9d-afde-0032d4e62e99 from DataBase
2013-10-31 16:39:27,790 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.org.ovirt.thread.pool-6-thread-18) CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity 44b1ef6c-8634-4e00-9632-b66125e36f22

Expected results:
Clean, readable, logs.

Additional info:

Comment 1 Allon Mureinik 2013-11-05 12:59:17 UTC

*** Bug 1026459 has been marked as a duplicate of this bug. ***

Comment 2 Sandro Bonazzola 2014-03-04 09:21:30 UTC

This is an automated message.
Re-targeting all non-blocker bugs still open on 3.4.0 to 3.4.1.

Comment 3 Ravi Nori 2014-04-30 15:38:31 UTC

Unable to reproduce this issue in current master. The log looks good

2014-04-30 11:32:45,164 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (org.ovirt.thread.pool-6-thread-41) SPMAsyncTask::ClearAsyncTask: Attempting to clear task 2d17c02c-187f-4f0f-9d16-b617484a623d
2014-04-30 11:32:45,165 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-41) START, SPMClearTaskVDSCommand( storagePoolId = 2eb8eafa-ef84-479a-ab27-1b57f4b720e5, ignoreFailoverLimit = false, taskId = 2d17c02c-187f-4f0f-9d16-b617484a623d), log id: 1e6f264b
2014-04-30 11:32:45,166 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-41) START, HSMClearTaskVDSCommand(HostName = 192.168.1.123, HostId = c76c77b3-7c48-42b3-9b19-6a088d41c77c, taskId=2d17c02c-187f-4f0f-9d16-b617484a623d), log id: 133b1589
2014-04-30 11:32:45,265 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-41) FINISH, HSMClearTaskVDSCommand, log id: 133b1589
2014-04-30 11:32:45,266 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-41) FINISH, SPMClearTaskVDSCommand, log id: 1e6f264b
2014-04-30 11:32:45,271 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (org.ovirt.thread.pool-6-thread-41) BaseAsyncTask::RemoveTaskFromDB: Removed task 2d17c02c-187f-4f0f-9d16-b617484a623d from DataBase

Comment 4 Greg Sheremeta 2014-04-30 15:41:29 UTC

Ravi, I'm pretty sure this got fixed way back in 3.3. I haven't seen since maybe 5 days I first noticed.

Comment 5 Ravi Nori 2014-04-30 15:43:42 UTC

Thanks Greg, closing as works for me

Comment 6 Allon Mureinik 2014-04-30 16:04:22 UTC

(In reply to Greg Sheremeta from comment #4)
> Ravi, I'm pretty sure this got fixed way back in 3.3. I haven't seen since
> maybe 5 days I first noticed.

(In reply to Ravi Nori from comment #5)
> Thanks Greg, closing as works for me

Changing close reason to UPSTREAM, as comments 4 and 5 concur this was indeed an issue back in some build of 3.3 (where the bug was reported), but was indeed fixed.

Comment 7 Pavel Stehlik 2014-08-12 14:35:25 UTC

This is upstream.