Fix: catch CloudRuntimeException in LibvirtGetVolumeStatsCommandWrapper.java #3949

slavkap · 2020-03-09T11:48:57Z

Description

When volume or storage pool are not found when LibvirtGetVolumeStatsCommandWrapper.java, CloudRuntimeException is thrown. All methods invoked by this command are throwing in most of the cases CloudRuntimeException and it's not handled in LibvirtGetVolumeStatsCommandWrapper.

For example if volume is not found, CloudStack agent throws this exception and it fills up the agent.log

DB record:
'29', '2', '1', '1', '2', NULL, NULL, 'nfsDisk', 'd644f5c6-bf70-4826-8d2b-d4bc373a9198', '5368709120', '/export/primary', 'efba7e17-dddd-4bbb-8233-347c9a5faaff', '1', '1', NULL, NULL, 'DATADISK', NULL, '3', NULL, NULL, '0', '2020-01-28 08:56:00', NULL, '2020-02-19 12:21:53', NULL, 'Ready', NULL, '21', NULL, NULL, NULL, '1', 'QCOW2', NULL, NULL, NULL, 'thin'

2020-03-06 17:38:06,775 DEBUG [kvm.storage.LibvirtStoragePool] (agentRequest-Handler-1:null) (logid:4858b218) volume: d644f5c6-bf70-4826-8d2b-d4bc373a9198 not exist on storage pool
2020-03-06 17:38:06,776 WARN [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:4858b218) Caught:
com.cloud.utils.exception.CloudRuntimeException: Can't find volume:d644f5c6-bf70-4826-8d2b-d4bc373a9198
at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:149)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtGetVolumeStatsCommandWrapper.getVolumeStat(LibvirtGetVolumeStatsCommandWrapper.java:63)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtGetVolumeStatsCommandWrapper.execute(LibvirtGetVolumeStatsCommandWrapper.java:52)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtGetVolumeStatsCommandWrapper.execute(LibvirtGetVolumeStatsCommandWrapper.java:40)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:78)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1483)
at com.cloud.agent.Agent.processRequest(Agent.java:640)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1053)
at com.cloud.utils.nio.Task.call(Task.java:83)
at com.cloud.utils.nio.Task.call(Task.java:29)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

If we handle the exception we will receive in management logs information like this for example:

DEBUG [c.c.a.m.AgentManagerImpl] (StatsCollector-2:ctx-bc39a30f) (logid:cd207a3e) Details from executing class com.cloud.agent.api.GetVolumeStatsCommand: Can't get vm disk stats: Unable to attach volume a43deb8f-b8b5-4e73-9043-76298cacd27b. Error: Error: volume 'a43deb8f-b8b5-4e73-9043-76298cacd27b' does not exist.

Types of changes

Breaking change (fix or feature that would cause existing functionality to change)
New feature (non-breaking change which adds functionality)
[ X] Bug fix (non-breaking change which fixes an issue)
Enhancement (improves an existing feature and functionality)
Cleanup (Code refactoring and cleanup, that may add test cases)

How Has This Been Tested?

tested with volumes on NFS and StorPool
on CloudStack version 4.11.2.0, 4.13.0.0 and master

DaanHoogland · 2020-03-09T12:09:15Z

@slavkap can you rebase your commit on latest head of the 4.13 branch, please?

When you migrate volume between data stores CS keeps the original UUID and changes the path of the volume. When volume is not found by the given path the agent throws CloudRuntimeException but it's not catched in LibvirtGetVolumeStatsCommandWrapper.java

DaanHoogland

code lgtm

DaanHoogland · 2020-03-09T13:49:14Z

@blueorangutan package

blueorangutan · 2020-03-09T13:49:27Z

@DaanHoogland a Jenkins job has been kicked to build packages. I'll keep you posted as I make progress.

blueorangutan · 2020-03-09T14:08:26Z

Packaging result: ✖centos6 ✔centos7 ✔debian. JID-1035

DaanHoogland · 2020-03-09T15:41:56Z

@blueorangutan test

blueorangutan · 2020-03-09T15:42:27Z

@DaanHoogland a Trillian-Jenkins test job (centos7 mgmt + kvm-centos7) has been kicked to run smoke tests

blueorangutan · 2020-03-09T23:33:06Z

Trillian test result (tid-1223)
Environment: kvm-centos7 (x2), Advanced Networking with Mgmt server 7
Total time taken: 26719 seconds
Marvin logs: https://github.com/blueorangutan/acs-prs/releases/download/trillian/pr3949-t1223-kvm-centos7.zip
Intermittent failure detected: /marvin/tests/smoke/test_privategw_acl.py
Smoke tests completed. 76 look OK, 1 have error(s)
Only failed tests results shown below:

Test	Result	Time (s)	Test File
test_02_vpc_privategw_static_routes	`Failure`	172.24	test_privategw_acl.py
test_03_vpc_privategw_restart_vpc_cleanup	`Failure`	171.98	test_privategw_acl.py
test_04_rvpc_privategw_static_routes	`Failure`	233.22	test_privategw_acl.py

Spaceman1984 · 2020-03-12T10:09:04Z

For testing, I changed the global setting volume.stats.interval to 10000 to make stats run every 10 seconds.

I did not get the exception in the description after migrating storage. A different null pointer was thrown every time stats ran, but as soon as the migration was finished the null pointer was no longer thrown.

To reproduce the runtime exception, I just removed the file from where it was in primary storage.

This PR would hide the runtime exception which I feel is not the desired behavior here if you would agree @slavkap ?

slavkap · 2020-03-12T13:38:18Z

@Spaceman1984 thanks that you spend time to test it! My bad that I didn't pull the latest changes and the fix is from #3884 where mgmt sends the path rather than the UUID of the volume. Unfortunately I couldn't reproduce the NPE that you hit.
I have tested it with the latest changes and in this case you wouldn't get the runtime exception. I think that the exception is not hidden because we send it back to the management for example like this:
DEBUG [c.c.a.m.AgentManagerImpl] (StatsCollector-2:ctx-bc39a30f) (logid:cd207a3e) Details from executing class com.cloud.agent.api.GetVolumeStatsCommand: Can't get vm disk stats: Unable to attach volume a43deb8f-b8b5-4e73-9043-76298cacd27b. Error: Error: volume 'a43deb8f-b8b5-4e73-9043-76298cacd27b' does not exist.
In such cases when CloudRuntimeException is thrown we won't fill up the agent's log with the stack trace

Spaceman1984 · 2020-03-13T07:37:21Z

This is the null pointer on the agent while migrating a volume, happens when stats are run.

java.lang.NullPointerException
	at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:128)
	at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtGetVolumeStatsCommandWrapper.getVolumeStat(LibvirtGetVolumeStatsCommandWrapper.java:64)
	at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtGetVolumeStatsCommandWrapper.execute(LibvirtGetVolumeStatsCommandWrapper.java:53)
	at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtGetVolumeStatsCommandWrapper.execute(LibvirtGetVolumeStatsCommandWrapper.java:41)
	at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:78)
	at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1500)
	at com.cloud.agent.Agent.processRequest(Agent.java:640)
	at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1053)
	at com.cloud.utils.nio.Task.call(Task.java:83)
	at com.cloud.utils.nio.Task.call(Task.java:29)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
2020-03-13 09:03:17,681 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:33b84d86) Seq 1-3499859860420296912:  { Ans: , MgmtId: 2130706689, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:128)\n\tat com.cloud.hypervisor.kvm.resource.wrapper.LibvirtGetVolumeStatsCommandWrapper.getVolumeStat(LibvirtGetVolumeStatsCommandWrapper.java:64)\n\tat com.cloud.hypervisor.kvm.resource.wrapper.LibvirtGetVolumeStatsCommandWrapper.execute(LibvirtGetVolumeStatsCommandWrapper.java:53)\n\tat com.cloud.hypervisor.kvm.resource.wrapper.LibvirtGetVolumeStatsCommandWrapper.execute(LibvirtGetVolumeStatsCommandWrapper.java:41)\n\tat com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:78)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1500)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:640)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1053)\n\tat com.cloud.utils.nio.Task.call(Task.java:83)\n\tat com.cloud.utils.nio.Task.call(Task.java:29)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\n\tat java.lang.Thread.run(Thread.java:748)\n","wait":0}}] }

I have also configured nfs in /etc/exports to be 2 separate entries:

/export *(rw,async,no_root_squash,no_subtree_check)
/alternate *(rw,async,no_root_squash,no_subtree_check)

I will test #3884 merged with this PR for the error on the management server, I haven't seen it yet.

lgtm was purely code related, ignorant of a functional problem being there

Spaceman1984 · 2020-03-16T09:02:18Z

I have tested #3884 with the code from this PR, I still get the null pointer while migrating a volume and stats run.

I wasn't able to reproduce the error in the description after migrating storage.

These are the steps I followed:

Change volume.stats.interval global setting to 10000
Create an instance
Stop the instance
Migrate the volume to a different primary storage
Check the management server log for the error.

Results:
No runtime exception

The next step I followed was:

Delete the file from primary storage

Result:
I have verified the error in management server logs:

2020-03-13 16:54:51,585 DEBUG [c.c.a.m.AgentManagerImpl] (StatsCollector-6:ctx-96e6db97) (logid:24749a89) Details from executing class com.cloud.agent.api.GetVolumeStatsCommand: Can't get vm disk stats: Can't find volume:76071844-5bab-42cc-a656-9c47cf0b7797

Seems like this PR improves logging of the error when a volume is missing from the storage pool, not when a volume was migrated.

slavkap · 2020-03-16T16:43:35Z

I will change the description, because when I have created this PR I wasn't updated my local repo with the latest changes with #3884. The CloudRuntimeException could be thrown in a lot of cases when volume stats command is executed, but I have tested it only if the volume is missing(migrated between datastores before the change from 3884). You can get it also, if for some reason can't get storage pool.

About the NPE if I find time I could check it, but this change doesn't causes it.

Spaceman1984 · 2020-03-17T08:51:30Z

@slavkap, I agree the NPE is not caused by this change.

Spaceman1984 · 2020-03-20T14:55:57Z

LGTM

DaanHoogland · 2020-03-20T15:19:55Z

@andrijapanicsb pure bug fix, do we include it given blockers are still out?

slavkap force-pushed the fix_CRE_of_migrated_volume_to_nfs branch from f72ac63 to da33574 Compare March 9, 2020 12:42

DaanHoogland previously approved these changes Mar 9, 2020

View reviewed changes

svenvogel added type:bug component:primary-storage labels Mar 9, 2020

slavkap changed the title ~~Fix CloudRuntimeException of migrated volume for Volume stats~~ Fix: catch CloudRuntimeException in LibvirtGetVolumeStatsCommandWrapper.java Mar 19, 2020

DaanHoogland requested review from andrijapanicsb, weizhouapache and yadvr March 20, 2020 15:25

weizhouapache approved these changes Mar 20, 2020

View reviewed changes

yadvr approved these changes Jun 12, 2020

View reviewed changes

yadvr added this to the 4.13.2.0 milestone Jun 12, 2020

yadvr merged commit 8b234bd into apache:4.13 Jun 12, 2020

DaanHoogland added the Severity:Major label Nov 10, 2020

Fix: catch CloudRuntimeException in LibvirtGetVolumeStatsCommandWrapper.java #3949

Fix: catch CloudRuntimeException in LibvirtGetVolumeStatsCommandWrapper.java #3949

Uh oh!

Conversation

slavkap commented Mar 9, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

Types of changes

How Has This Been Tested?

Uh oh!

DaanHoogland commented Mar 9, 2020

Uh oh!

DaanHoogland left a comment

Choose a reason for hiding this comment

Uh oh!

DaanHoogland commented Mar 9, 2020

Uh oh!

blueorangutan commented Mar 9, 2020

Uh oh!

blueorangutan commented Mar 9, 2020

Uh oh!

DaanHoogland commented Mar 9, 2020

Uh oh!

blueorangutan commented Mar 9, 2020

Uh oh!

blueorangutan commented Mar 9, 2020

Uh oh!

Spaceman1984 commented Mar 12, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

slavkap commented Mar 12, 2020

Uh oh!

Spaceman1984 commented Mar 13, 2020

Uh oh!

Spaceman1984 commented Mar 16, 2020

Uh oh!

slavkap commented Mar 16, 2020

Uh oh!

Spaceman1984 commented Mar 17, 2020

Uh oh!

Spaceman1984 commented Mar 20, 2020

Uh oh!

DaanHoogland commented Mar 20, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

slavkap commented Mar 9, 2020 •

edited

Loading

Spaceman1984 commented Mar 12, 2020 •

edited

Loading