Bug 1153043

Created attachment 947224 [details]
engine.log - example from auto test via java sdk

I am unable to reproduce this on current master and ovirt-engine-3.5.

Please re-test

I cannot reproduce it in vt6 too.

But the problem where engine stuck for 1 hour still appears, can u please take
a look to engine.log I attached?

The case is just add disk with DiscCreator via javasdk.
And I still get "Query execution failed due to insufficient permissions." in GetTasksStatusesByTasksIDsQuery.

I'd suggest you to concentrate in the following log messages (extracted from the attached log file):

2014-10-05 19:15:27,073 INFO  [org.ovirt.engine.core.bll.AddDiskCommand] (ajp-/127.0.0.1:8702-8) [disks_create_f09bd592-9330-47f8] Running command: AddDiskCommand internal: false. Entities affected :  ID: 303fadc9-4b7c-4c3d-9c13-2c77d60d20e3 Type: StorageAction group CREATE_DISK with role type USER
2014-10-05 19:15:27,255 INFO  [org.ovirt.engine.core.bll.AddImageFromScratchCommand] (ajp-/127.0.0.1:8702-8) [3b3c144b] Running command: AddImageFromScratchCommand internal: true. Entities affected :  ID: 303fadc9-4b7c-4c3d-9c13-2c77d60d20e3 Type: Storage
2014-10-05 19:15:27,375 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp-/127.0.0.1:8702-8) [3b3c144b] START, CreateImageVDSCommand( storagePoolId = e27a3be1-7d97-41d6-9086-af40b29a8648, ignoreFailoverLimit = false, storageDomainId = 303fadc9-4b7c-4c3d-9c13-2c77d60d20e3, imageGroupId = 29cf124c-afba-4a96-b5f2-64c20a925889, imageSizeInBytes = 1073741824, volumeFormat = COW, newImageId = f4bd87cb-602e-4cc4-ad4c-575e686d0c3a, newImageDescription = ), log id: dbf09d3
2014-10-05 19:15:27,380 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp-/127.0.0.1:8702-8) [3b3c144b] -- executeIrsBrokerCommand: calling 'createVolume' with two new parameters: description and UUID
2014-10-05 19:15:27,540 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp-/127.0.0.1:8702-8) [3b3c144b] FINISH, CreateImageVDSCommand, return: f4bd87cb-602e-4cc4-ad4c-575e686d0c3a, log id: dbf09d3
2014-10-05 19:15:27,672 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (ajp-/127.0.0.1:8702-8) [3b3c144b] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command d45b2f04-a77c-427c-857b-7e2bf3437758
2014-10-05 19:15:27,673 INFO  [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (ajp-/127.0.0.1:8702-8) [3b3c144b] CommandMultiAsyncTasks::AttachTask: Attaching task 00424a9b-b52f-4077-ab14-2af28417f1e0 to command d45b2f04-a77c-427c-857b-7e2bf3437758.
2014-10-05 19:15:27,715 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (ajp-/127.0.0.1:8702-8) [3b3c144b] Adding task 00424a9b-b52f-4077-ab14-2af28417f1e0 (Parent Command AddDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2014-10-05 19:15:27,791 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-8) [3b3c144b] Correlation ID: disks_create_f09bd592-9330-47f8, Job ID: 9d8340ac-bfd1-4e46-9245-b3407ed5d237, Call Stack: null, Custom Event ID: -1, Message: Add-Disk operation of 'users__disk' was initiated by userportal1.
2014-10-05 19:15:27,792 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (ajp-/127.0.0.1:8702-8) [3b3c144b] BaseAsyncTask::startPollingTask: Starting to poll task 00424a9b-b52f-4077-ab14-2af28417f1e0.
2014-10-05 19:15:27,867 ERROR [org.ovirt.engine.core.bll.GetTasksStatusesByTasksIDsQuery] (ajp-/127.0.0.1:8702-8) Query execution failed due to insufficient permissions.

What is happening here is that the operation to create the disk returns async tasks, and the RESTAPI has been asked to perform this in a sync fashion. In these circumstances the RESTAPI will check the status of the tasks once per second, for ever. In this case that check is failing, but the REST API will continue checking, for ever. Eventually the timeout of the communication between the web server and the engine (1 hour, see /etc/httpd/conf.d/z-ovirt-engine.conf: timeout=3600) will expire and the operation will fail from the point of view of the caller. However the RESTAPI will continue checking, and if the check keeps failing the thread will be effectively useless. If this keeps happening eventually all threads will be useless (there are already two threads in that situation in the attaed log) and the engine will block completely.

Hi Ravi,

I ran the job where this probelm appeared, and it still don't work.

I can now see in log:
2014-11-24 21:30:23,651 ERROR [org.ovirt.engine.core.bll.GetTasksStatusesByTasksIDsQuery] (ajp-/127.0.0.1:8702-5) Query execution failed due to insufficient permissions. Users can only query tasks started by them.
2014-11-24 21:30:24,370 ERROR [org.ovirt.engine.core.bll.GetTasksStatusesByTasksIDsQuery] (ajp-/127.0.0.1:8702-8) Query execution failed due to insufficient permissions. Users can only query tasks started by them.
2014-11-24 21:30:24,652 ERROR [org.ovirt.engine.core.bll.GetTasksStatusesByTasksIDsQuery] (ajp-/127.0.0.1:8702-5) Query execution failed due to insufficient permissions. Users can only query tasks started by them.
2014-11-24 21:30:25,371 ERROR [org.ovirt.engine.core.bll.GetTasksStatusesByTasksIDsQuery] (ajp-/127.0.0.1:8702-8) Query execution failed due to insufficient permissions. Users can only query tasks started by them

while the async_task table is empty...

engine=# select * from async_tasks;
 task_id | action_type | status | result | step_id | command_id | started_at | storage_pool_id | task_type | vdsm_task_id | root_command_id | user_id 
---------+-------------+--------+--------+---------+------------+------------+-----------------+-----------+--------------+-----------------+---------
(0 rows)

Created attachment 960910 [details]
engine.log

Works OK in vt13.1.

rhev 3.5.0 was released. closing.