Bug 1684267 - Vdsm return GeneralError and log a traceback when a lease does not exit
Summary: Vdsm return GeneralError and log a traceback when a lease does not exit
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: vdsm
Classification: oVirt
Component: Core
Version: 4.30.8
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ovirt-4.3.2
: 4.30.11
Assignee: Eyal Shenitzky
QA Contact: Evelina Shames
URL:
Whiteboard:
Depends On:
Blocks: 1685025
TreeView+ depends on / blocked
 
Reported: 2019-02-28 20:26 UTC by Nir Soffer
Modified: 2019-03-19 10:05 UTC (History)
5 users (show)

Fixed In Version: vdsm-4.30.11
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-03-19 10:05:18 UTC
oVirt Team: Storage
Embargoed:

Attachments (Terms of Use)
vdsm log from OST (492.08 KB, text/plain)
2019-02-28 20:26 UTC, Nir Soffer 		no flags Details
engine log with even worse traceback (4.20 MB, text/plain)
2019-02-28 20:51 UTC, Nir Soffer 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 98191 0 master MERGED xlease: Raise a specific public error for non-existing lease 2020-11-26 15:27:36 UTC
oVirt gerrit 98401 0 ovirt-4.3 MERGED xlease: Raise a specific public error for non-existing lease 2020-11-26 15:27:11 UTC

Description Nir Soffer 2019-02-28 20:26:29 UTC 
Created attachment 1539623 [details]
vdsm log from OST

Description of problem:

When asking for info about a non-existing lease, vdsm fail with GeneralError, and
log a traceback.

Here is example from vdsm logs during OST boostrap phase:

1. Engine fetches non-existing lease info

2019-02-27 13:37:21,968-0500 INFO  (jsonrpc/1) [vdsm.api] START lease_info(lease={u'sd_id': u'b370b91d-00b5-4f62-9270-ac0acd47d075', u'lease_id': u'3500eb82-e5e2-4e24-b41c-ea02d9f6adee'}) from=::ffff:192.168.201.4,43920, flow_id=117dec74-ad59-4b12-8148-b2c130337c10, task_id=9c297d41-0aa7-4c74-b268-b710e666bc6c (api:48)

2. Since the lease does not exits, vdsm fails

2019-02-27 13:37:21,987-0500 INFO  (jsonrpc/1) [vdsm.api] FINISH lease_info error=No such lease 3500eb82-e5e2-4e24-b41c-ea02d9f6adee from=::ffff:192.168.201.4,43920, flow_id=117dec74-ad59-4b12-8148-b2c130337c10, task_id=9c297d41-0aa7-4c74-b268-b710e666bc6c (api:52)
2019-02-27 13:37:21,988-0500 ERROR (jsonrpc/1) [storage.TaskManager.Task] (Task='9c297d41-0aa7-4c74-b268-b710e666bc6c') Unexpected error (task:875)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in lease_info
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 50, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 3702, in lease_info
    info = dom.lease_info(lease.lease_id)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 674, in lease_info
    return vol.lookup(lease_id)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/xlease.py", line 553, in lookup
    raise NoSuchLease(lease_id)
NoSuchLease: No such lease 3500eb82-e5e2-4e24-b41c-ea02d9f6adee

But vdsm returns a GeneralException code=100 to engine - so engine cannot handle
this error.

Vdsm should treat this as expected error, returning a specific public error, and
log a info message. Same way we handle non-existing volume in Volume.info.

Version-Release number of selected component (if applicable):
master, but all version since 4.1 have this issue.

How reproducible:
Always

Steps to Reproduce:
1. Call Lease.info for non existing lease

Actual results:
- vdsm return general error
- Traceback in vdsm log

Expected results:
- return public error about non-existing lease
- Log info message about the missing lease

Additional info:

The xlease module raises only private errors: NoSuchLease, LeaseExists,
LeaseUpdating, etc.

Some or all of these errors should be converted to public errors in 
(vdsm.storage.exception), so engine can take the right action when it receive
the error.

How to reproduce:

$ cat lease.json 
{
    "lease": {
        "sd_id": "fb5cab8c-08ba-4781-9532-ccc78ddb21ec",
        "lease_id": "c6684192-01f8-4f1d-94a9-59e070f5af88"
    }
}

$ vdsm-client -f lease.json Lease info
vdsm-client: Command Lease.info with args {u'lease': {u'sd_id': u'fb5cab8c-08ba-4781-9532-ccc78ddb21ec', u'lease_id': u'c6684192-01f8-4f1d-94a9-59e070f5af88'}} failed:
(code=100, message=No such lease c6684192-01f8-4f1d-94a9-59e070f5af88)

Note: code=100 - this is a GeneralException.

Setting severity to medium because of the bad error, preventing error handling
in engine.
Comment 1 Nir Soffer 2019-02-28 20:51:18 UTC 
Created attachment 1539636 [details]
engine log with even worse traceback

The GeneralError on vdsm side cause a horrible traceback on engine side:

2019-02-27 13:37:21,996-05 DEBUG [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (default task-1) [117dec74-ad59-4b12-8148-b2c130337c10] Exception: org.ovirt.engine.core.vdsbroker.irsbroker.IRSErrorException: IRSGenericException: IRSErrorException: Failed to GetVmLeaseInfoVDS, error = No such lease 3500eb82-e5e2-4e24-b41c-ea02d9f6adee, code = 100
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand.createDefaultConcreteException(IrsBrokerCommand.java:60) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:223) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:193) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmLeaseInfoVDSCommand.executeIrsBrokerCommand(GetVmLeaseInfoVDSCommand.java:21) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand.lambda$executeVDSCommand$0(IrsBrokerCommand.java:98) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxy.runInControlledConcurrency(IrsProxy.java:274) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand.executeVDSCommand(IrsBrokerCommand.java:95) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:65) [vdsbroker.jar:]
        at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:31) [dal.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:396) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand$$super(Unknown Source) [vdsbroker.jar:]
        at sun.reflect.GeneratedMethodAccessor254.invoke(Unknown Source) [:1.8.0_191]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_191]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_191]
        at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51) [weld-core-impl-3.0.5.Final.jar:3.0.5.Final]
        at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78) [weld-core-impl-3.0.5.Final.jar:3.0.5.Final]
        at org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12) [common.jar:]
        at sun.reflect.GeneratedMethodAccessor61.invoke(Unknown Source) [:1.8.0_191]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_191]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_191]
        at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73) [weld-core-impl-3.0.5.Final.jar:3.0.5.Final]
        at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84) [weld-core-impl-3.0.5.Final.jar:3.0.5.Final]
        at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72) [weld-core-impl-3.0.5.Final.jar:3.0.5.Final]
        at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56) [weld-core-impl-3.0.5.Final.jar:3.0.5.Final]
        at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79) [weld-core-impl-3.0.5.Final.jar:3.0.5.Final]
        at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68) [weld-core-impl-3.0.5.Final.jar:3.0.5.Final]
        at org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown Source) [vdsbroker.jar:]
        at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runVdsCommand(CommandBase.java:2075) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.lease.GetVmLeaseInfoCommand.executeCommand(GetVmLeaseInfoCommand.java:65) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1157) [bll.jar:]
...
Comment 2 Eyal Shenitzky 2019-03-10 10:15:08 UTC 
Steps to Reproduce:
1. Create a VM
2. Add a lease to the VM

Actual results:
An error message appears in the vdsm log:

2019-03-10 03:56:06,403-0400 INFO  (jsonrpc/3) [vdsm.api] FINISH lease_info error=No such lease dfe3ee51-936d-45ff-a02b-e00b5ca5d2f6 from=::ffff:192.168.201.4,58392, flow_id=fc3dfe2d-ea8e-4fd9-bd6b-6b8e26762e09, task_id=459c7101-cb95-41c4-bf56-cbb86490f28b (api:52)
2019-03-10 03:56:06,403-0400 ERROR (jsonrpc/3) [storage.TaskManager.Task] (Task='459c7101-cb95-41c4-bf56-cbb86490f28b') Unexpected error (task:875)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in lease_info
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 50, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 3702, in lease_info
    info = dom.lease_info(lease.lease_id)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 683, in lease_info
    return vol.lookup(lease_id)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/xlease.py", line 553, in lookup
    raise NoSuchLease(lease_id)
NoSuchLease: No such lease dfe3ee51-936d-45ff-a02b-e00b5ca5d2f6
2019-03-10 03:56:06,404-0400 INFO  (jsonrpc/3) [storage.TaskManager.Task] (Task='459c7101-cb95-41c4-bf56-cbb86490f28b') aborting: Task is aborted: u'No such lease dfe3ee51-936d-45ff-a02b-e00b5ca5d2f6' - code 100 (task:1181)
2019-03-10 03:56:06,404-0400 ERROR (jsonrpc/3) [storage.Dispatcher] FINISH lease_info error=No such lease dfe3ee51-936d-45ff-a02b-e00b5ca5d2f6 (dispatcher:87)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/dispatcher.py", line 74, in wrapper
    result = ctask.prepare(func, *args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 108, in wrapper
    return m(self, *a, **kw)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 1189, in prepare
    raise self.error
NoSuchLease: No such lease dfe3ee51-936d-45ff-a02b-e00b5ca5d2f6
2019-03-10 03:56:06,404-0400 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Lease.info failed (error 100) in 0.02 seconds (__init__:312)


Expected results:
The error is expected and the error message should be shown as:

2019-03-10 12:11:02,828+0200 INFO  (jsonrpc/3) [vdsm.api] FINISH lease_info error=No such lease: 'lease=9e3ad570-cc9c-48f1-b356-4125e8f50b92' from=::ffff:10.35.0.228,37038,
 flow_id=e3e30160-2e6f-49eb-b15e-f877c8020bb8, task_id=2bcea296-c92b-4cd2-8135-dac12b4b96c6 (api:52)
2019-03-10 12:11:02,829+0200 INFO  (jsonrpc/3) [storage.TaskManager.Task] (Task='2bcea296-c92b-4cd2-8135-dac12b4b96c6') aborting: Task is aborted: "No such lease: 'lease=9e
3ad570-cc9c-48f1-b356-4125e8f50b92'" - code 936 (task:1181)
2019-03-10 12:11:02,829+0200 INFO  (jsonrpc/3) [storage.Dispatcher] FINISH lease_info error=No such lease: 'lease=9e3ad570-cc9c-48f1-b356-4125e8f50b92' (dispatcher:81)
2019-03-10 12:11:02,829+0200 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Lease.info failed (error 936) in 0.02 seconds (__init__:312)
Comment 3 Evelina Shames 2019-03-17 13:37:30 UTC 
Verified on engine 4.3.2.1 vdsm 4.30.11.
Comment 4 Sandro Bonazzola 2019-03-19 10:05:18 UTC 
This bugzilla is included in oVirt 4.3.2 release, published on March 19th 2019.

Since the problem described in this bug report should be
resolved in oVirt 4.3.2 release, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.
Note You need to log in before you can comment on or make changes to this bug.