Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1295778

Summary: [audit_log] VDSM $hostname command failed: Internal JSON-RPC error.
Product: [oVirt] ovirt-engine Reporter: Jiri Belka <jbelka>
Component: GeneralAssignee: Piotr Kliczewski <pkliczew>
Status: CLOSED CURRENTRELEASE QA Contact: Jiri Belka <jbelka>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 3.6.2CC: bugs, jbelka, mgoldboi, oourfali, pkliczew, pstehlik
Target Milestone: ovirt-3.6.3Flags: rule-engine: ovirt-3.6.z+
rule-engine: exception+
mgoldboi: planning_ack+
rule-engine: devel_ack+
pstehlik: testing_ack+
Target Release: 3.6.3.3   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-03-11 07:24:34 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 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