Bug 1153043 - [mla] query execution failed due to insufficient permissions for add disk as user in user level api
Summary: [mla] query execution failed due to insufficient permissions for add disk as ...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine
Version: 3.5.0
Hardware: Unspecified
OS: Unspecified
urgent
urgent
Target Milestone: ---
: 3.5.0
Assignee: Ravi Nori
QA Contact: Ondra Machacek
URL:
Whiteboard: infra
Depends On:
Blocks: rhev35rcblocker rhev35gablocker
TreeView+ depends on / blocked
 
Reported: 2014-10-15 13:24 UTC by Ondra Machacek
Modified: 2016-02-10 19:27 UTC (History)
15 users (show)

Fixed In Version: org.ovirt.engine-root-3.5.0-23
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-02-17 17:14:41 UTC
oVirt Team: Infra


Attachments (Terms of Use)
engine.log - example from auto test via java sdk (1.11 MB, text/plain)
2014-10-15 13:26 UTC, Ondra Machacek
no flags Details
engine.log (23.87 KB, text/plain)
2014-11-24 19:41 UTC, Ondra Machacek
no flags Details


Links
System ID Priority Status Summary Last Updated
oVirt gerrit 34517 master MERGED engine : query execution failed due to insufficient permissions Never
oVirt gerrit 34616 master MERGED engine : Add User Id to async tasks table Never
oVirt gerrit 34843 ovirt-engine-3.5 MERGED engine : Add User Id to async tasks table Never
oVirt gerrit 34844 ovirt-engine-3.5 MERGED engine : query execution failed due to insufficient permissions Never
oVirt gerrit 35612 master MERGED engine : [mla] query execution failed due to insufficient permissions Never
oVirt gerrit 35733 ovirt-engine-3.5 MERGED engine : [mla] query execution failed due to insufficient permissions Never

Description Ondra Machacek 2014-10-15 13:24:14 UTC
Description of problem:


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

How reproducible:
always

Steps to Reproduce:
1. curl -k -X POST -H "Accept: application/xml" -H "Content-Type: application/xml" -H "Filter: True" \
    -u $U -d "<disk><storage_domains><storage_domain id=\"7e41d2dd-3c70-4c7a-b9f4-50ac6d3905c2\"/></storage_domains><interface>virtio</interface><format>cow</format><size>1073741824</size></disk>" \
    $URL/disks

Actual results:
<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<disk href="/api/disks/cc6991a4-c741-4c4f-afb7-f1318ec565f2" id="cc6991a4-c741-4c4f-afb7-f1318ec565f2">
    <actions>
        <link href="/api/disks/cc6991a4-c741-4c4f-afb7-f1318ec565f2/export" rel="export"/>
        <link href="/api/disks/cc6991a4-c741-4c4f-afb7-f1318ec565f2/move" rel="move"/>
        <link href="/api/disks/cc6991a4-c741-4c4f-afb7-f1318ec565f2/copy" rel="copy"/>
    </actions>
    <name>_Disk1</name>
    <link href="/api/disks/cc6991a4-c741-4c4f-afb7-f1318ec565f2/permissions" rel="permissions"/>
    <link href="/api/disks/cc6991a4-c741-4c4f-afb7-f1318ec565f2/statistics" rel="statistics"/>
    <link href="/api/disks/cc6991a4-c741-4c4f-afb7-f1318ec565f2/creation_status/577e9ce2-28c6-430a-b437-99cd55f7925d" rel="creation_status"/>
    <alias>_Disk1</alias>
    <image_id>a279e6f0-9751-467f-82b0-1645268c759c</image_id>
    <storage_domains>
        <storage_domain id="7e41d2dd-3c70-4c7a-b9f4-50ac6d3905c2"/>
    </storage_domains>
    <size>1073741824</size>
    <provisioned_size>1073741824</provisioned_size>
    <actual_size>0</actual_size>
    <status>
        <state>locked</state>
    </status>
    <interface>virtio</interface>
    <format>cow</format>
    <sparse>true</sparse>
    <bootable>false</bootable>
    <shareable>false</shareable>
    <wipe_after_delete>false</wipe_after_delete>
    <propagate_errors>false</propagate_errors>
</disk>
<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<fault>
    <reason>Operation Failed</reason>
    <detail>query execution failed due to insufficient permissions.</detail>
</fault>


Expected results:
same output without "query execution failed due to insufficient permissions"

Additional info:

Comment 1 Ondra Machacek 2014-10-15 13:26:44 UTC
Created attachment 947224 [details]
engine.log - example from auto test via java sdk

Comment 3 Ravi Nori 2014-10-15 16:03:01 UTC
I am unable to reproduce this on current master and ovirt-engine-3.5.

Please re-test

Comment 4 Ondra Machacek 2014-10-21 13:32:14 UTC
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.

Comment 5 Juan Hernández 2014-10-27 16:50:14 UTC
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.

Comment 6 Ondra Machacek 2014-11-24 19:32:00 UTC
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)

Comment 7 Ondra Machacek 2014-11-24 19:41:52 UTC
Created attachment 960910 [details]
engine.log

Comment 8 Ondra Machacek 2014-12-05 12:29:34 UTC
Works OK in vt13.1.

Comment 9 Eyal Edri 2015-02-17 17:14:41 UTC
rhev 3.5.0 was released. closing.


Note You need to log in before you can comment on or make changes to this bug.