Skip to content

Improve logs in NfsSecondaryStorageResource class - #7211

Merged
DaanHoogland merged 5 commits into
apache:mainfrom
scclouds:improve-logs-in-nfssecondarystorageresource-class
Sep 28, 2023
Merged

Improve logs in NfsSecondaryStorageResource class#7211
DaanHoogland merged 5 commits into
apache:mainfrom
scclouds:improve-logs-in-nfssecondarystorageresource-class

Conversation

@SadiJr

@SadiJr SadiJr commented Feb 13, 2023

Copy link
Copy Markdown
Contributor

Description

The NfsSecondaryStorageResource class is responsible for performing certain operations involving secondary storage. However, it does not present enough logs for effective troubleshooting. Thus, new logs were added to this class, aiming to facilitate future troubleshooting involving secondary storage.

Types of changes

  • Breaking change (fix or feature that would cause existing functionality to change)
  • New feature (non-breaking change which adds functionality)
  • 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)

Feature/Enhancement Scale or Bug Severity

Bug Severity

  • BLOCKER
  • Critical
  • Major
  • Minor
  • Trivial

Screenshots (if appropriate):

How Has This Been Tested?

It was tested in a local lab:

  1. I performed actions that use the secondary storage, like creating a VM using a template that is on secondary storage;
  2. I read the logs to see if they were improved;
  3. Before, the logs did not have enough information to perform an efficient troubleshooting;
  4. Now, with improved logs, the troubleshooting will be easier.

@codecov

codecov Bot commented Feb 13, 2023

Copy link
Copy Markdown

Codecov Report

Merging #7211 (1b7fdf4) into main (45616aa) will increase coverage by 0.01%.
The diff coverage is 0.00%.

@@             Coverage Diff              @@
##               main    #7211      +/-   ##
============================================
+ Coverage     29.16%   29.18%   +0.01%     
- Complexity    30377    30399      +22     
============================================
  Files          5100     5100              
  Lines        358273   358292      +19     
  Branches      52304    52305       +1     
============================================
+ Hits         104496   104552      +56     
+ Misses       239406   239363      -43     
- Partials      14371    14377       +6     
Flag Coverage Δ
simulator-marvin-tests 25.21% <0.00%> (+0.01%) ⬆️
uitests 4.87% <ø> (ø)
unit-tests 14.40% <ø> (+<0.01%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Files Changed Coverage Δ
.../storage/resource/NfsSecondaryStorageResource.java 0.00% <0.00%> (ø)

... and 25 files with indirect coverage changes

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

@sonarqubecloud

Copy link
Copy Markdown

SonarCloud Quality Gate failed.    Quality Gate failed

Bug A 0 Bugs
Vulnerability A 0 Vulnerabilities
Security Hotspot A 0 Security Hotspots
Code Smell A 0 Code Smells

0.0% 0.0% Coverage
0.0% 0.0% Duplication

@kiranchavala

Copy link
Copy Markdown
Member

@SadiJr

Could you please provide a sample snippet of the new improved logs so that i can verify it.

@RodrigoDLopez RodrigoDLopez left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Some improvement in logs messages. Lgtm

@DaanHoogland DaanHoogland added this to the 4.19.0.0 milestone Jun 22, 2023
@SadiJr

SadiJr commented Aug 22, 2023

Copy link
Copy Markdown
Contributor Author

@SadiJr

Could you please provide a sample snippet of the new improved logs so that i can verify it.

@kiranchavala sorry for the delay to answer you, sure I can provide some samples:

cloud.log:2023-08-22 16:52:45,628 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-2:null) Executing command "ListVolumeCommand" [{"store":{"_url":"nfs://192.168.122.250/mnt/secondary/vmware","_role":"Image","nfsVersion":"4"},"secUrl":"nfs://192.168.122.250/mnt/secondary/vmware","contextMap":{"logid":"f0bc454e"},"wait":0,"bypassHostMaintenance":false}].
cloud.log:2023-08-22 16:52:45,628 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-2:null) Trying to get root directory from secondary storage URL [nfs://192.168.122.250/mnt/secondary/vmware] using NFS version [4].
cloud.log:2023-08-22 16:52:45,628 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-2:null) Determined host 192.168.122.250 corresponds to IP 192.168.122.250
cloud.log:2023-08-22 16:52:45,630 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-2:null) Mounting device with nfs-style path of 192.168.122.250:/mnt/secondary/vmware
cloud.log:2023-08-22 16:52:45,630 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-2:null) mount nfs://192.168.122.250/mnt/secondary/vmware on /mnt/SecStorage/8601b06f-9918-378d-b31a-c4b7d8b492d4 nfsVersion=4
cloud.log:2023-08-22 16:52:45,630 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-2:null) making available /mnt/SecStorage/8601b06f-9918-378d-b31a-c4b7d8b492d4 on nfs://192.168.122.250/mnt/secondary/vmware
cloud.log:2023-08-22 16:52:45,630 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-2:null) local folder for mount will be /mnt/SecStorage/8601b06f-9918-378d-b31a-c4b7d8b492d4
cloud.log:2023-08-22 16:52:45,631 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-2:null) Executing command [mount ].
cloud.log:2023-08-22 16:52:45,637 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-2:null) Successfully executed process [6769] for command [mount ].
cloud.log:2023-08-22 16:52:45,637 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-2:null) Some device already mounted at /mnt/SecStorage/8601b06f-9918-378d-b31a-c4b7d8b492d4, no need to mount nfs://192.168.122.250/mnt/secondary/vmware
cloud.log:2023-08-22 16:52:45,741 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Executing command "ListTemplateCommand" [{"store":{"_url":"nfs://192.168.122.250/mnt/secondary/vmware","_role":"Image","nfsVersion":"4"},"nfsVersion":"4","contextMap":{"logid":"f0bc454e"},"wait":0,"bypassHostMaintenance":false}].
cloud.log:2023-08-22 16:52:45,741 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Trying to get root directory from secondary storage URL [nfs://192.168.122.250/mnt/secondary/vmware] using NFS version [4].
cloud.log:2023-08-22 16:52:45,741 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Determined host 192.168.122.250 corresponds to IP 192.168.122.250
cloud.log:2023-08-22 16:52:45,741 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Mounting device with nfs-style path of 192.168.122.250:/mnt/secondary/vmware
cloud.log:2023-08-22 16:52:45,741 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) mount nfs://192.168.122.250/mnt/secondary/vmware on /mnt/SecStorage/8601b06f-9918-378d-b31a-c4b7d8b492d4 nfsVersion=4
cloud.log:2023-08-22 16:52:45,741 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) making available /mnt/SecStorage/8601b06f-9918-378d-b31a-c4b7d8b492d4 on nfs://192.168.122.250/mnt/secondary/vmware
cloud.log:2023-08-22 16:52:45,741 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) local folder for mount will be /mnt/SecStorage/8601b06f-9918-378d-b31a-c4b7d8b492d4
cloud.log:2023-08-22 16:52:45,742 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Executing command [mount ].
cloud.log:2023-08-22 16:52:45,747 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Successfully executed process [6772] for command [mount ].
cloud.log:2023-08-22 16:52:45,747 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Some device already mounted at /mnt/SecStorage/8601b06f-9918-378d-b31a-c4b7d8b492d4, no need to mount nfs://192.168.122.250/mnt/secondary/vmware
cloud.log:2023-08-22 16:52:48,115 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-4:null) Executing command "ReadyCommand" [{"dcId":2,"hostId":69,"enableHumanReadableSizes":true,"contextMap":{"logid":"f0bc454e"},"wait":0,"bypassHostMaintenance":false}].
cloud.log:2023-08-22 16:52:48,187 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:null) Executing command "ReadyCommand" [{"dcId":2,"hostId":69,"msHostList":["192.168.122.212"],"lbAlgorithm":"static","lbCheckInterval":0,"enableHumanReadableSizes":true,"contextMap":{"logid":"f0bc454e"},"wait":0,"bypassHostMaintenance":false}].
cloud.log:2023-08-22 16:52:54,823 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:null) Executing command "GetStorageStatsCommand" [{"store":{"_url":"nfs://192.168.122.250/mnt/secondary/vmware","_role":"Image","nfsVersion":"4"},"nfsVersion":"4","contextMap":{"logid":"99844c35"},"wait":0,"bypassHostMaintenance":false}].
cloud.log:2023-08-22 16:52:54,823 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:null) Trying to get root directory from secondary storage URL [nfs://192.168.122.250/mnt/secondary/vmware] using NFS version [4].

Please tell me if you need more information.

@JoaoJandre JoaoJandre left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

CLGTM

@kiranchavala

Copy link
Copy Markdown
Member

@blueorangutan package

@blueorangutan

Copy link
Copy Markdown

@kiranchavala a [SF] Jenkins job has been kicked to build packages. It will be bundled with KVM, XenServer and VMware SystemVM templates. I'll keep you posted as I make progress.

@blueorangutan

Copy link
Copy Markdown

Packaging result [SF]: ✔️ el7 ✔️ el8 ✔️ el9 ✔️ debian ✔️ suse15. SL-JID 7141

@kiranchavala kiranchavala left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, Tested it manually by deleting a template on the secondary secstorage and the logs have improved.

Before the change

2023-09-28 09:29:30,273 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) Request:Seq 3-8414412953788373825:  { Cmd , MgmtId: 32988284846932, via: 3, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/210/d0db18d6-4eec-437d-98fd-3434195d9625.qcow2","uuid":"18cd1d18-ed03-4173-ae51-9583c732b8a8","id":"210","format":"QCOW2","accountId":"2","hvm":"false","displayText":"Docker-Ubuntu22-04","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"NFS://10.0.32.4/acs/secondary/ref-trl-5653-k-M7-kiran-chavala/ref-trl-5653-k-M7-kiran-chavala-sec1","_role":"Image"}},"name":"d0db18d6-4eec-437d-98fd-3434195d9625","size":"(8.00 GB) 8589934592","hypervisorType":"KVM","bootable":"false","uniqueName":"d0db18d6-4eec-437d-98fd-3434195d9625","directDownload":"false","deployAsIs":"false"}},"wait":"0","bypassHostMaintenance":"false"}}] }

2023-09-28 09:29:30,275 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) Processing command: org.apache.cloudstack.storage.command.DeleteCommand

2023-09-28 09:29:30,275 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Determined host 10.0.32.4 corresponds to IP 10.0.32.4
2023-09-28 09:29:30,276 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Mounting device with nfs-style path of 10.0.32.4:/acs/secondary/ref-trl-5653-k-M7-kiran-chavala/ref-trl-5653-k-M7-kiran-chavala-sec1
2023-09-28 09:29:30,276 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) mount NFS://10.0.32.4/acs/secondary/ref-trl-5653-k-M7-kiran-chavala/ref-trl-5653-k-M7-kiran-chavala-sec1 on /mnt/SecStorage/35b44d96-2df0-3e86-abaa-6c53d66d1479 nfsVersion=null
2023-09-28 09:29:30,276 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) making available /mnt/SecStorage/35b44d96-2df0-3e86-abaa-6c53d66d1479 on NFS://10.0.32.4/acs/secondary/ref-trl-5653-k-M7-kiran-chavala/ref-trl-5653-k-M7-kiran-chavala-sec1
2023-09-28 09:29:30,277 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) local folder for mount will be /mnt/SecStorage/35b44d96-2df0-3e86-abaa-6c53d66d1479
2023-09-28 09:29:30,278 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Executing: mount
2023-09-28 09:29:30,280 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Executing while with timeout : 1440000
2023-09-28 09:29:30,289 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:null) Execution is successful.

after the change

2023-09-28 09:23:50,306 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) Request:Seq 2-5897745187018375271:  { Cmd , MgmtId: 32988989489992, via: 2, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/203/137a32f6-4070-39dd-b6a1-ccd668260936.qcow2","origUrl":"http://10.0.3.122/Fedora/Fedora-Server-KVM-37-1.7.x86_64.qcow2","uuid":"a16a53a7-3d72-4e1b-8825-8fe7ba3e6db3","id":"203","format":"QCOW2","accountId":"2","checksum":"{SHA-512}668d2f0a73d912fad7dc0ef9fcbbff325f220dfcc497f6aa49a87632acbd377264b9642340522de7be6d5603ff589267206bdd7e780ecfdfa396a10b596fe3e4","hvm":"true","displayText":"fed1","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"NFS://10.0.32.4/acs/secondary/ref-trl-5732-k-M7-kiran-chavala/ref-trl-5732-k-M7-kiran-chavala-sec1","_role":"Image"}},"name":"203-2-8b5b9946-0a02-3704-aace-befaeb93327e","size":"(7.00 GB) 7516192768","hypervisorType":"KVM","bootable":"false","uniqueName":"203-2-8b5b9946-0a02-3704-aace-befaeb93327e","directDownload":"false","deployAsIs":"false"}},"wait":"0","bypassHostMaintenance":"false"}}] }

2023-09-28 09:23:50,315 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) Processing command: org.apache.cloudstack.storage.command.DeleteCommand

2023-09-28 09:23:50,317 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:null) Executing command "DeleteCommand" [{"data":{"path":"template/tmpl/2/203/137a32f6-4070-39dd-b6a1-ccd668260936.qcow2","origUrl":"http://10.0.3.122/Fedora/Fedora-Server-KVM-37-1.7.x86_64.qcow2","uuid":"a16a53a7-3d72-4e1b-8825-8fe7ba3e6db3","id":203,"format":"QCOW2","accountId":2,"checksum":"{SHA-512}668d2f0a73d912fad7dc0ef9fcbbff325f220dfcc497f6aa49a87632acbd377264b9642340522de7be6d5603ff589267206bdd7e780ecfdfa396a10b596fe3e4","hvm":true,"displayText":"fed1","imageDataStore":{"_url":"NFS://10.0.32.4/acs/secondary/ref-trl-5732-k-M7-kiran-chavala/ref-trl-5732-k-M7-kiran-chavala-sec1","_role":"Image"},"name":"203-2-8b5b9946-0a02-3704-aace-befaeb93327e","size":7516192768,"hypervisorType":"KVM","bootable":false,"uniqueName":"203-2-8b5b9946-0a02-3704-aace-befaeb93327e","directDownload":false,"deployAsIs":false},"contextMap":{"logid":"d2338bcf","job":"job-49"},"wait":0,"bypassHostMaintenance":false}].

2023-09-28 09:23:50,317 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:null) Trying to get root directory from secondary storage URL [NFS://10.0.32.4/acs/secondary/ref-trl-5732-k-M7-kiran-chavala/ref-trl-5732-k-M7-kiran-chavala-sec1] using NFS version [null].
2023-09-28 09:23:50,318 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:null) Determined host 10.0.32.4 corresponds to IP 10.0.32.4
2023-09-28 09:23:50,319 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:null) Mounting device with nfs-style path of 10.0.32.4:/acs/secondary/ref-trl-5732-k-M7-kiran-chavala/ref-trl-5732-k-M7-kiran-chavala-sec1
2023-09-28 09:23:50,319 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:null) mount NFS://10.0.32.4/acs/secondary/ref-trl-5732-k-M7-kiran-chavala/ref-trl-5732-k-M7-kiran-chavala-sec1 on /mnt/SecStorage/0e6c5290-0899-3fb1-bd99-0902b1d2dd86 nfsVersion=null
2023-09-28 09:23:50,320 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:null) making available /mnt/SecStorage/0e6c5290-0899-3fb1-bd99-0902b1d2dd86 on NFS://10.0.32.4/acs/secondary/ref-trl-5732-k-M7-kiran-chavala/ref-trl-5732-k-M7-kiran-chavala-sec1
2023-09-28 09:23:50,320 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:null) local folder for mount will be /mnt/SecStorage/0e6c5290-0899-3fb1-bd99-0902b1d2dd86
2023-09-28 09:23:50,321 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:null) Executing: mount
2023-09-28 09:23:50,328 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:null) Executing while with timeout : 1440000
2023-09-28 09:23:50,336 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:null) Execution is successful.

@DaanHoogland
DaanHoogland merged commit 2b35a02 into apache:main Sep 28, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

6 participants