NAS BACKUP PLUGIN ERROR

[fermosan]

ISSUE TYPE

• Bug Report

COMPONENT NAME

NAS BACKUP PLUGIN

CLOUDSTACK VERSION

4.20

CONFIGURATION

OS / ENVIRONMENT

Ubuntu 22.04 / NFS

SUMMARY

The Jobs failing with error "jobresult":{"errorcode":530,"errortext":"Failed to create VM backup"},"jobinstancetype":"Backup","created":"2024-12-05T13:42:24+0200","completed":"2024-12-05T13:42:24+0200","jobid":"b22226f7-2d2b-43fa-801c-61e5af8a6870"}}

STEPS TO REPRODUCE

Backup plugin has been enabled on the Zone side.  
An offering is created. 
VM is assigned to backup offering 
a Backup is initiated manually from UI. 

EXPECTED RESULTS

Take instance backup

ACTUAL RESULTS

A directory is created in the /tmp of the hypervisor running the VM
A folder under the VM name is created in the mounted nfs 
The UI returns "Failed to create VM backup"

[Pearl1594]

@fermosan are there any further logs you can share to help debug further? Either Management server logs or the hypervisor host where the VM is running?

[rohityadavcloud]

@fermosan can you check write permissions on the NFS storage and share the KVM agent logs in debug level? Was the instance stopped or running, was it started once after initial deployment?

[fermosan]

Hello @rohityadavcloud.

Running Instance:
On the cloudstack-agent side we have:

2024-12-09 11:44:05,584 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:[]) (logid:8cc3fef2) Request:Seq 191-1230327123202298444: { Cmd , MgmtId: 95530338908, via: 191, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.backup.TakeBackupCommand":{"vmName":"i-2-596-VM","backupPath":"i2-596-VM/2024.12.09.13.44.05","backupRepoType":"nfs","backupRepoAddress":"172.31.103.251:/data/col1/BACKUP","wait":"0","bypassHostMaintenance":"false"}}] } 2024-12-09 11:44:05,585 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:[]) (logid:8cc3fef2) Processing command: org.apache.cloudstack.backup.TakeBackupCommand 2024-12-09 11:44:05,619 DEBUG [utils.script.Script] (Script-3:[]) (logid:) Piped commands executed successfully 2024-12-09 11:44:05,619 DEBUG [resource.wrapper.LibvirtTakeBackupCommandWrapper] (agentRequest-Handler-4:[]) (logid:8cc3fef2) Failed to take VM backup: 2024-12-09 11:44:05,620 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:[]) (logid:8cc3fef2) Seq 191-1230327123202298444: { Ans: , MgmtId: 95530338908, via: 191, Ver: v1, Flags: 110, [{"org.apache.cloudstack.backup.BackupAnswer":{"result":"false","details":"","wait":"0","bypassHostaintenance":"false"}}] }

On the management server log:

2024-12-09 13:47:10,391 DEBUG [c.c.a.ApiServer] (qtp1800976873-22047:[ctx-d2bbf912, ctx-f313a3b4]) (logid:25c2cfd9) CIDRs from which account 'Account [{"accountName":"admin","id":2,"uuid":"4a0c196f-2989-11ea-bc02-b8ca3a64c3a4"}]' is allowed to perform API calls: 0.0.0.0/0,::/0 2024-12-09 13:47:10,393 DEBUG [c.c.a.m.ClusteredAgentAttache] (API-Job-Executor-81:[ctx-3b1e1215, job-83850, ctx-cd856b49]) (logid:7202eaa8) Seq 175-1230327123202298459: Routed from 95530338908 2024-12-09 13:47:10,394 DEBUG [c.c.a.t.Request] (API-Job-Executor-81:[ctx-3b1e1215, job-83850, ctx-cd856b49]) (logid:7202eaa8) Seq 191-1230327123202298459: Sending { Cmd , MgmtId: 95530338908, via: 191(mdr2srvkvm01), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.backup.TakeBackupCommand":{"vmName":"i-2-596-VM","backupPath":"i-2-596-VM/2024.12.09.13.47.10","backupRepoType":"nfs","backupRepoAddress":"172.31.103.251:/data/col1/BACKUP","wait":"0","bypassHostMaintenance":"false"}}] } 2024-12-09 13:47:10,403 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker] (qtp1800976873-22047:[ctx-d2bbf912, ctx-f313a3b4]) (logid:25c2cfd9) RoleService is enabled. We will use it instead of StaticRoleBasedAPIAccessChecker. 2024-12-09 13:47:10,404 DEBUG [o.a.c.r.ApiRateLimitServiceImpl] (qtp1800976873-22047:[ctx-d2bbf912, ctx-f313a3b4]) (logid:25c2cfd9) API rate limiting is disabled. We will not use ApiRateLimitService. 2024-12-09 13:47:10,436 DEBUG [c.c.a.t.Request] (AgentManager-Handler-13:[]) (logid:) Seq 191-1230327123202298459: Processing: { Ans: , MgmtId: 95530338908, via: 191, Ver: v1, Flags: 110, [{"org.apache.cloudstack.backup.BackupAnswer":{"result":"false","details":"","wait":"0","bypassHostMaintenance":"false"}}] } 2024-12-09 13:47:10,436 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-13:[]) (logid:) Seq 175-1230327123202298459: No more commands found 2024-12-09 13:47:10,436 DEBUG [c.c.a.t.Request] (API-Job-Executor-81:[ctx-3b1e1215, job-83850, ctx-cd856b49]) (logid:7202eaa8) Seq 191-1230327123202298459: Received: { Ans: , MgmtId: 95530338908, via: 191(mdr2srvkvm01), Ver: v1, Flags: 110, { BackupAnswer } } 2024-12-09 13:47:10,444 WARN [o.a.c.m.w.WebhookServiceImpl] (API-Job-Executor-81:[ctx-3b1e1215, job-83850, ctx-cd856b49]) (logid:7202eaa8) Skipping delivering event [ID: null, description: {"event":"BACKUP.CREATE","status":"Completed"}] to any webhook as account ID is missing 2024-12-09 13:47:10,444 WARN [o.a.c.f.e.EventDistributorImpl] (API-Job-Executor-81:[ctx-3b1e1215, job-83850, ctx-cd856b49]) (logid:7202eaa8) Failed to publish event [category: ActionEvent, type: BACKUP.CREATE] on bus webhookEventBus 2024-12-09 13:47:10,458 INFO [c.c.a.ApiServlet] (qtp1800976873-22047:[ctx-d2bbf912, ctx-f313a3b4]) (logid:25c2cfd9) (userId=2 accountId=2 sessionId=node0uurhl6pbu62fo5g8lyenjrh414) 194.219.182.165 -- GET jobId=7202eaa8-deea-4881-82e6-cc62ac9114b6&command=queryAsyncJobResult&response=json&sessionkey=tQ7Q3JCVI7ZCb0J9NNiZyGf4a6w 200 {"queryasyncjobresultresponse":{"accountid":"4a0c196f-2989-11ea-bc02-b8ca3a64c3a4","account":"admin","domainid":"2a06fb0a-2989-11ea-bc02-b8ca3a64c3a4","domainpath":"ROOT","userid":"4a0c279e-2989-11ea-bc02-b8ca3a64c3a4","cmd":"org.apache.cloudstack.api.command.user.backup.CreateBackupCmd","jobstatus":0,"jobprocstatus":0,"jobresultcode":0,"jobinstancetype":"Backup","managementserverid":95530338908,"created":"2024-12-09T13:47:10+0200","jobid":"7202eaa8-deea-4881-82e6-cc62ac9114b6"}} 2024-12-09 13:47:10,459 DEBUG [c.c.a.ApiServlet] (qtp1800976873-22047:[ctx-d2bbf912, ctx-f313a3b4]) (logid:25c2cfd9) ===END=== 194.219.182.165 -- GET jobId=7202eaa8-deea-4881-82e6-cc62ac9114b6&command=queryAsyncJobResult&response=json&sessionkey=tQ7Q3JCVI7ZCb0J9NNiZyGf4a6w 2024-12-09 13:47:10,468 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-81:[ctx-3b1e1215, job-83850]) (logid:7202eaa8) Complete async job-83850, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Failed to create VM backup"}

Stopped Instance:

On the cloudstack-agent side we have:

2024-12-09 11:55:12,282 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:[]) (logid:e900457e) Request:Seq 191-1230327123202298492: { Cmd , MgmtId: 95530338908, via: 191, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.backup.TakeBackupCommand":{"vmName":"i-2-596-VM","backupPath":"i-2-596-VM/2024.12.09.13.55.12","backupRepoType":"nfs","backupRepoAddress":"172.31.103.251:/data/col1/BACKUP","volumePaths":["/mnt/3f13461f-efe4-3232-ae24-62803d0b7263/e777f35f-a03f-4642-86c7-51d643fe54fd","/mnt/3f13461f-efe4-3232-ae24-62803d0b7263/d433e70c-82d1-48dc-87ba-62c0ca28fa17"],"wait":"0","bypassHostMaintenance":"false"}}] } 2024-12-09 11:55:12,283 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:[]) (logid:e900457e) Processing command: org.apache.cloudstack.backup.TakeBackupCommand 2024-12-09 11:55:12,319 DEBUG [utils.script.Script] (Script-10:[]) (logid:) Piped commands executed successfully 2024-12-09 11:55:12,319 DEBUG [resource.wrapper.LibvirtTakeBackupCommandWrapper] (agentRequest-Handler-2:[]) (logid:e900457e) Failed to take VM backup: 2024-12-09 11:55:12,319 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:[]) (logid:e900457e) Seq 191-1230327123202298492: { Ans: , MgmtId: 95530338908, via: 191, Ver: v1, Flags: 110, [{"org.apache.cloudstack.backup.BackupAnswer":{"result":"false","details":"","wait":"0","bypassHostMaintenance":"false"}}] }

On the management server log:

2024-12-09 13:55:15,369 INFO [c.c.a.ApiServlet] (qtp1800976873-22222:[ctx-404a879a, ctx-8780cfdd]) (logid:dc21b917) (userId=2 accountId=2 sessionId=node0uurhl6pbu62fo5g8lyenjrh414) 194.219.182.165 -- GET jobId=e900457e-d1d9-40a8-af96-e520d48b7323&command=queryAsyncJobResult&response=json&sessionkey=tQ7Q3JCVI7ZCb0J9NNiZyGf4a6w 200 {"queryasyncjobresultresponse":{"accountid":"4a0c196f-2989-11ea-bc02-b8ca3a64c3a4","account":"admin","domainid":"2a06fb0a-2989-11ea-bc02-b8ca3a64c3a4","domainpath":"ROOT","userid":"4a0c279e-2989-11ea-bc02-b8ca3a64c3a4","cmd":"org.apache.cloudstack.api.command.user.backup.CreateBackupCmd","jobstatus":2,"jobprocstatus":0,"jobresultcode":530,"jobresulttype":"object","jobresult":{"errorcode":530,"errortext":"Failed to create VM backup"},"jobinstancetype":"Backup","created":"2024-12-09T13:55:12+0200","completed":"2024-12-09T13:55:12+0200","jobid":"e900457e-d1d9-40a8-af96-e520d48b7323"}}

All users writing in the NFS are squashed and is verified that they can write.

[Pearl1594]

Can you please try running this command on the host directly where the operation is run when you initiate the backup operation - say for VM i-2-596-VM:

/usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/nasbackup.sh -o backup -v i-2-596-VM -t nfs -s 172.31.103.251:/data/col1/BACKUP -p <secondary store mount path on host>/i2-596-VM/2024.12.09.13.44.05

You'd need to substitute the secondary store mount path for the last parameter. This may provide further insight on the issue at hand.

[fermosan]

Hello, i play around with the nasbackup.sh script to figure out what is going wrong.
First indication is:
error: operation failed: failed to format image: 'Image is not in qcow2 format'

However, both disks in the VM are QCOW2

`qemu-img info /mnt/3f13461f-efe4-3232-ae24-62803d0b7263/d433e70c-82d1-48dc-87ba-62c0ca28fa17
image: /mnt/3f13461f-efe4-3232-ae24-62803d0b7263/d433e70c-82d1-48dc-87ba-62c0ca28fa17
file format: qcow2
virtual size: 25 GiB (26843545600 bytes)
disk size: 22.8 GiB
cluster_size: 65536
Format specific information:
compat: 1.1
compression type: zlib
lazy refcounts: false
refcount bits: 16
corrupt: false
extended l2: false

qemu-img info /mnt/3f13461f-efe4-3232-ae24-62803d0b7263/e777f35f-a03f-4642-86c7-51d643fe54fd
image: /mnt/3f13461f-efe4-3232-ae24-62803d0b7263/e777f35f-a03f-4642-86c7-51d643fe54fd
file format: qcow2
virtual size: 20 GiB (21474836480 bytes)
disk size: 10.2 GiB
cluster_size: 65536
Format specific information:
compat: 1.1
compression type: zlib
lazy refcounts: false
refcount bits: 16
corrupt: false
extended l2: false
`

[fermosan]

The error for qcow2 format is caused (in my case) on the NFS server impementation of protocol 4.0. Reverting to protocol 3.0 solves the issue. I believe it has to do something with sparse file support on the NFS server side.

Maybe is a good idea to have a DEBUG flag (with appropriate changes in the script as well) on the cloudstack config section for the backup plugin. Other backup plugins have already implemented such functionality for debugging purposes.

Also, an update of the documentation for the plugin to indicate that the NFS server must not use squash and anonymous uid/gid. In my case it was also breaking the creation of backup since virsh was trying to chown to root/root the backup files.