Bug 1295778 - [audit_log] VDSM $hostname command failed: Internal JSON-RPC error.
Summary: [audit_log] VDSM $hostname command failed: Internal JSON-RPC error.
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: General
Version: 3.6.2
Hardware: Unspecified
OS: Unspecified
unspecified
medium vote
Target Milestone: ovirt-3.6.3
: 3.6.3.3
Assignee: Piotr Kliczewski
QA Contact: Jiri Belka
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-01-05 12:29 UTC by Jiri Belka
Modified: 2016-03-11 07:24 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-03-11 07:24:34 UTC
oVirt Team: Infra
rule-engine: ovirt-3.6.z+
rule-engine: exception+
mgoldboi: planning_ack+
rule-engine: devel_ack+
pstehlik: testing_ack+


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 51549 0 master MERGED hooks: make sure to handle vdsm exception in the bridge 2016-02-02 10:12:11 UTC
oVirt gerrit 51631 0 master MERGED core: new hook error code 2016-01-20 16:23:46 UTC
oVirt gerrit 52544 0 ovirt-engine-3.6 MERGED core: new hook error code 2016-02-09 12:54:41 UTC
oVirt gerrit 52984 0 ovirt-3.6 MERGED hooks: make sure to handle vdsm exception in the bridge 2016-02-04 09:26:55 UTC
oVirt gerrit 53292 0 refs/tags/ovirt-engine-3.6.3 ABANDONED core: new hook error code 2016-02-09 13:06:11 UTC
oVirt gerrit 53293 0 ovirt-engine-3.6.3 MERGED core: new hook error code 2016-02-10 09:00:40 UTC
oVirt gerrit 53696 0 ovirt-3.6.3 MERGED hooks: make sure to handle vdsm exception in the bridge 2016-02-18 12:37:33 UTC

Description Jiri Belka 2016-01-05 12:29:22 UTC
Description of problem:

If a vdsm hook fails, there's all the time VDS_BROKER_COMMAND_FAILURE - VDSM $hostname command failed: Internal JSON-RPC error.

IMO the message is far from being optimal and useful for end-user (it is shown in UI.)

Discovered in BZ1220838.

~~~
2016-01-05 13:21:10,793 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (org.ovirt.thread.pool-7-thread-3) [3d6d5341] START, HotUnPlugDiskVDSCommand(HostName = dell-r210ii-13.example.com, HotPlugDiskVDSParameters:{runAsync='true', hostId='fdf32332-6254-4724-b0bf-92ef0413ae70', vmId='3e14f4ee-1ef9-4147-81df-aaa218f5bb38', diskId='777305cc-a939-466e-b83e-f81b05338476', addressMap='
[bus=0x00, domain=0x0000, function=0x0, slot=0x03, type=pci]'}), log id: 384b6a6d
2016-01-05 13:21:11,822 WARN  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (org.ovirt.thread.pool-7-thread-3) [3d6d5341] Unexpected return value: StatusForXmlRpc [code=-32603, message=Inter
nal JSON-RPC error.]
2016-01-05 13:21:11,822 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (org.ovirt.thread.pool-7-thread-3) [3d6d5341] Failed in 'HotUnPlugDiskVDS' method
2016-01-05 13:21:11,828 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-7-thread-3) [3d6d5341] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: VDSM dell-r210ii-13.example.com command failed: Internal JSON-RPC error.
2016-01-05 13:21:11,828 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (org.ovirt.thread.pool-7-thread-3) [3d6d5341] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand' return value 'StatusOnlyReturnForXmlRpc [status=StatusForXmlRpc [code=-32603, message=Internal JSON-RPC error.]]'
2016-01-05 13:21:11,828 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (org.ovirt.thread.pool-7-thread-3) [3d6d5341] HostName = dell-r210ii-13.example.com
2016-01-05 13:21:11,828 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (org.ovirt.thread.pool-7-thread-3) [3d6d5341] Command 'HotUnPlugDiskVDSCommand(HostName = dell-r210ii-13.example.com, HotPlugDiskVDSParameters:{runAsync='true', hostId='fdf32332-6254-4724-b0bf-92ef0413ae70', vmId='3e14f4ee-1ef9-4147-81df-aaa218f5bb38', diskId='777305cc-a939-466e-b83e-f81b05338476', addressMap
='[bus=0x00, domain=0x0000, function=0x0, slot=0x03, type=pci]'})' execution failed: VDSGenericException: VDSErrorException: Failed to HotUnPlugDiskVDS, error = Internal JSON-RPC error., code = -32603
2016-01-05 13:21:11,828 DEBUG [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (org.ovirt.thread.pool-7-thread-3) [3d6d5341] Exception: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorExcepti
on: VDSGenericException: VDSErrorException: Failed to HotUnPlugDiskVDS, error = Internal JSON-RPC error., code = -32603
        at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createDefaultConcreteException(VdsBrokerCommand.java:75) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:211) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:192) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand.executeVdsBrokerCommand(HotUnPlugDiskVDSCommand.java:15) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:110) [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:33) [dal.jar:]
        at org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:467) [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:2095) [bll.jar:]
        at org.ovirt.engine.core.bll.AbstractDiskVmCommand.performPlugCommand(AbstractDiskVmCommand.java:105) [bll.jar:]
        at org.ovirt.engine.core.bll.HotPlugDiskToVmCommand.executeVmCommand(HotPlugDiskToVmCommand.java:136) [bll.jar:]
        at org.ovirt.engine.core.bll.VmCommand.executeCommand(VmCommand.java:104) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1215) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1359) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1983) [bll.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:174) [utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:116) [utils.jar:]
        at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1396) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:378) [bll.jar:]
        at org.ovirt.engine.core.bll.MultipleActionsRunner.executeValidatedCommand(MultipleActionsRunner.java:202) [bll.jar:]
        at org.ovirt.engine.core.bll.MultipleActionsRunner.runCommands(MultipleActionsRunner.java:170) [bll.jar:]
        at org.ovirt.engine.core.bll.MultipleActionsRunner$2.run(MultipleActionsRunner.java:179) [bll.jar:]
        at org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil$InternalWrapperRunnable.run(ThreadPoolUtil.java:92) [utils.jar:]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_65]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_65]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_65]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_65]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_65]

~~~

Version-Release number of selected component (if applicable):
rhevm-backend-3.6.2-0.1.el6.noarch

How reproducible:
100%

Steps to Reproduce:
1. make a vdsm hook which would return '1' (simple shell script is enough)
2. refresh caps from engine to have the hook available
3. run an action which would execute the hook (i used before disk hotplug hook, thus i did hot-unplug of a vm's disk)

Actual results:
VDSM $hostname command failed: Internal JSON-RPC error all the time when vdsm hooks does not return success

Expected results:
msg should be either more end-user useful or silent

Additional info:

Comment 2 Piotr Kliczewski 2016-01-07 14:41:15 UTC
You received the most generic error that something unexpected happened on vdsm side. Please provide vdsm logs.

Comment 4 Jiri Belka 2016-01-07 14:57:44 UTC
# cat /usr/libexec/vdsm/hooks/before_disk_hotunplug/00_test 
#!/bin/sh

{ echo "horrorrrrrrrrrrrrrrrrrrrrrrrrrrr!" ; exit 1; }

Comment 5 Piotr Kliczewski 2016-01-07 15:18:57 UTC
Here is the stack trace from vdsm side:

jsonrpc.Executor/4::ERROR::2016-01-05 12:40:10,471::__init__::526::jsonrpc.JsonRpcServer::(_serveRequest) Internal server error
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 521, in _serveRequest
    res = method(**params)
  File "/usr/share/vdsm/rpc/Bridge.py", line 277, in _dynamicMethod
    result = fn(*methodArgs)
  File "/usr/share/vdsm/API.py", line 474, in hotunplugDisk
    return curVm.hotunplugDisk(params)
  File "/usr/share/vdsm/virt/vm.py", line 2638, in hotunplugDisk
    params=drive.custom)
  File "/usr/share/vdsm/hooks.py", line 308, in before_disk_hotunplug
    params=params)
  File "/usr/share/vdsm/hooks.py", line 111, in _runHooksDir
    raise HookError(err)
HookError

Comment 6 Jiri Belka 2016-02-17 17:37:39 UTC
I still see 'Message: VDSM $host command failed: Internal JSON-RPC error.'

Are you sure the fix is part of 4.17.21-0.el7ev.noarch / rhevm-3.6.3.2-0.1.el6.noarch ?

Comment 7 Piotr Kliczewski 2016-02-17 17:46:24 UTC
I will check it the build. It is possible that the fix is not yet there.

Comment 8 Piotr Kliczewski 2016-02-18 10:12:19 UTC
It looks like I missed one backport on vdsm side. Moving to POST to fix it.

Comment 9 Red Hat Bugzilla Rules Engine 2016-02-18 10:12:24 UTC
Target release should be placed once a package build is known to fix a issue. Since this bug is not modified, the target version has been reset. Please use target milestone to plan a fix for a oVirt release.

Comment 10 Jiri Belka 2016-02-25 11:03:48 UTC
ok, rhevm-3.6.3.3-0.1.el6.noarch
	
Feb 25, 2016 12:02:39 PM
	
Failed to unplug disk default1_Disk2 from VM default1 (User: admin@internal).
	
	
Feb 25, 2016 12:02:39 PM
	
VDSM dell-r210ii-13 command failed: Hook Error


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