search

NAUbackup / VmBackup

XenServer simple backup script
228 stars 61 forks source link

Warning Message #58

Closed aroldo-biz closed 6 years ago

aroldo-biz commented 6 years ago

One of my virtual machines is generating a warning message every day. What are the possible causes for warning in the backup of a virtual machine?

Logs:

2017-10-25-(00:01:02) - WARNING vdi-export dup - remove vm-export=IE9 - Win7 2017-10-25-(00:01:02) - VmBackup config loaded from: /etc/vmbackup.cfg 2017-10-25-(00:01:02) - VmBackup.py running with these settings: 2017-10-25-(00:01:02) - backup_dir = /mnt/backup/xenserver0/ 2017-10-25-(00:01:02) - status_log = /mnt/backup/xenserver0/status.log 2017-10-25-(00:01:02) - compress = False 2017-10-25-(00:01:02) - max_backups = 1 2017-10-25-(00:01:02) - vdi_export_format = vhd 2017-10-25-(00:01:02) - pool_db_backup = 1 2017-10-25-(00:01:02) - exclude (cnt)= 0 2017-10-25-(00:01:02) - exclude: 2017-10-25-(00:01:02) - vdi-export (cnt)= 3 2017-10-25-(00:01:02) - vdi-export: Sophos UTM, Web-Dev, IE9 - Win7 2017-10-25-(00:01:02) - vm-export (cnt)= 1 2017-10-25-(00:01:02) - vm-export: IE10 - Win7 2017-10-25-(00:01:02) - SUCCESS check of parameters 2017-10-25-(00:01:02) - =========================== 2017-10-25-(00:01:02) - VmBackup running on xenserver ... 2017-10-25-(00:01:02) - =========================== 2017-10-25-(00:01:02) - Check if backup directory /mnt/backup/xenserver0/ is writable ... 2017-10-25-(00:01:02) - /bin/touch "/mnt/backup/xenserver0/00VMbackupWriteTest" 2017-10-25-(00:01:02) - Success: backup directory area is writable 2017-10-25-(00:01:02) - =========================== 2017-10-25-(00:01:02) - Space before backups: df -Th /mnt/backup/xenserver0/ 2017-10-25-(00:01:02) - Filesystem Type Size Used Avail Use% Mounted on 2017-10-25-(00:01:02) - 192.168.1.19:/mnt/volume1/backup nfs4 1.8T 662G 1.1T 38% /mnt/backup 2017-10-25-(00:01:02) - begin backup_pool_metadata * 2017-10-25-(00:01:02) - ignore: NOT master 2017-10-25-(00:01:02) - ** vdi-export= ***** 2017-10-25-(00:01:02) - vdi-export begin Sophos UTM 2017-10-25-(00:01:02) - vdi-export - vm_name: Sophos UTM max_backups: 1 2017-10-25-(00:01:02) - new backup_dir: /mnt/backup/xenserver0/Sophos UTM/backup-2017-10-25-(00:01:02) 2017-10-25-(00:01:02) - Writing vm config file. 2017-10-25-(00:01:02) - Writing disk info 2017-10-25-(00:01:02) - vbd: OpaqueRef:2ccc4c41-3c43-7466-1155-bc9d8e727e2b 2017-10-25-(00:01:02) - vbd: OpaqueRef:4d324ffc-cdd7-2f7a-70c7-945da73a430b 2017-10-25-(00:01:02) - disk: New virtual disk - begin 2017-10-25-(00:01:02) - Writing VIF info 2017-10-25-(00:01:02) - Writing VIF: 1 2017-10-25-(00:01:02) - Writing VIF: 3 2017-10-25-(00:01:02) - Writing VIF: 0 2017-10-25-(00:01:02) - Writing VIF: 2 2017-10-25-(00:01:02) - vdi-export begin xe command sequence 2017-10-25-(00:01:02) - power-state ( RO) : running 2017-10-25-(00:01:02) - vm is running 2017-10-25-(00:01:02) - 1.cmd: /opt/xensource/bin/xe vdi-list uuid=cf125882-2254-4145-a2b0-32882b303f25 2017-10-25-(00:01:02) - uuid ( RO) : cf125882-2254-4145-a2b0-32882b303f25 2017-10-25-(00:01:02) - name-label ( RW): New virtual disk 2017-10-25-(00:01:02) - name-description ( RW): 2017-10-25-(00:01:02) - sr-uuid ( RO): fc7f4b77-06a9-a874-e5ff-0bf356ef0c9a 2017-10-25-(00:01:02) - virtual-size ( RO): 128849018880 2017-10-25-(00:01:02) - sharable ( RO): false 2017-10-25-(00:01:02) - read-only ( RO): false 2017-10-25-(00:01:02) - 2017-10-25-(00:01:02) - 2017-10-25-(00:01:02) - check for prev-vdi-snapshot: SNAP_Sophos-UTM_New-virtual-disk 2017-10-25-(00:01:02) - cleanup old-snap-vdi-uuid: 2c30ca52-da5b-4e97-ba71-878db4118a87 2017-10-25-(00:01:02) - cmd: /opt/xensource/bin/xe vdi-destroy uuid=2c30ca52-da5b-4e97-ba71-878db4118a87 2017-10-25-(00:01:03) - This operation cannot be performed because this VDI is in use by some other operation 2017-10-25-(00:01:03) - vdi: 2c30ca52-da5b-4e97-ba71-878db4118a87 (SNAP_Sophos-UTM_New-virtual-disk) 2017-10-25-(00:01:03) - operation: destroy 2017-10-25-(00:01:03) - WARNING /opt/xensource/bin/xe vdi-destroy uuid=2c30ca52-da5b-4e97-ba71-878db4118a87 2017-10-25-(00:01:03) - 2.cmd: /opt/xensource/bin/xe vdi-snapshot uuid=cf125882-2254-4145-a2b0-32882b303f25 2017-10-25-(00:01:09) - snap-uuid: 2354eaf1-283f-431c-b123-f46aee0c9589 2017-10-25-(00:01:09) - 3.cmd: /opt/xensource/bin/xe vdi-param-set uuid=2354eaf1-283f-431c-b123-f46aee0c9589 name-label="SNAP_Sophos-UTM_New-virtual-disk" 2017-10-25-(00:01:09) - 4.cmd: /opt/xensource/bin/xe vdi-export format=vhd uuid=2354eaf1-283f-431c-b123-f46aee0c9589 filename="/mnt/backup/xenserver0/Sophos UTM/backup-2017-10-25-(00:01:02)/Sophos UTM.vhd" 2017-10-25-(00:10:53) - vdi-export success 2017-10-25-(00:10:53) - 5.cmd: /opt/xensource/bin/xe vdi-destroy uuid=2354eaf1-283f-431c-b123-f46aee0c9589 2017-10-25-(00:10:55) - vdi-export end 2017-10-25-(00:10:55) - success: /mnt/backup/xenserver0/Sophos UTM/backup-2017-10-25-(00:01:02)/Sophos UTM.vhd : 42G 2017-10-25-(00:10:55) - Deleting oldest backup /mnt/backup/xenserver0/Sophos UTM/backup-2017-10-24-(00:01:02) 2017-10-25-(00:10:56) - VmBackup vdi-export Sophos UTM - WARNING t:9 2017-10-25-(00:10:56) - vdi-export begin Web-Dev 2017-10-25-(00:10:56) - vdi-export - vm_name: Web-Dev max_backups: 1 2017-10-25-(00:10:56) - new backup_dir: /mnt/backup/xenserver0/Web-Dev/backup-2017-10-25-(00:10:56) 2017-10-25-(00:10:56) - Writing vm config file. 2017-10-25-(00:10:56) - Writing disk info 2017-10-25-(00:10:56) - vbd: OpaqueRef:71624d69-4874-8b68-0d71-b6f6f5ebe8fb 2017-10-25-(00:10:56) - vbd: OpaqueRef:e1a2cce3-0c54-43e3-f1cb-eafea3d17c3b 2017-10-25-(00:10:56) - disk: Dev 0 - begin 2017-10-25-(00:10:56) - Writing VIF info 2017-10-25-(00:10:56) - Writing VIF: 0 2017-10-25-(00:10:56) - vdi-export begin xe command sequence 2017-10-25-(00:10:56) - power-state ( RO) : running 2017-10-25-(00:10:56) - vm is running 2017-10-25-(00:10:56) - 1.cmd: /opt/xensource/bin/xe vdi-list uuid=3d1d5526-889c-40c8-8dc5-0477c7cf2d36 2017-10-25-(00:10:56) - uuid ( RO) : 3d1d5526-889c-40c8-8dc5-0477c7cf2d36 2017-10-25-(00:10:56) - name-label ( RW): Dev 0 2017-10-25-(00:10:56) - name-description ( RW): Created by template provisioner 2017-10-25-(00:10:56) - sr-uuid ( RO): fc7f4b77-06a9-a874-e5ff-0bf356ef0c9a 2017-10-25-(00:10:56) - virtual-size ( RO): 1181116006400 2017-10-25-(00:10:56) - sharable ( RO): false 2017-10-25-(00:10:56) - read-only ( RO): false 2017-10-25-(00:10:56) - 2017-10-25-(00:10:56) - 2017-10-25-(00:10:56) - check for prev-vdi-snapshot: SNAP_Web-Dev_Dev-0 2017-10-25-(00:10:56) - 2.cmd: /opt/xensource/bin/xe vdi-snapshot uuid=3d1d5526-889c-40c8-8dc5-0477c7cf2d36 2017-10-25-(00:11:01) - snap-uuid: 11e5de51-40b0-42b3-8eb0-85ef77e34e01 2017-10-25-(00:11:01) - 3.cmd: /opt/xensource/bin/xe vdi-param-set uuid=11e5de51-40b0-42b3-8eb0-85ef77e34e01 name-label="SNAP_Web-Dev_Dev-0" 2017-10-25-(00:11:02) - 4.cmd: /opt/xensource/bin/xe vdi-export format=vhd uuid=11e5de51-40b0-42b3-8eb0-85ef77e34e01 filename="/mnt/backup/xenserver0/Web-Dev/backup-2017-10-25-(00:10:56)/Web-Dev.vhd" 2017-10-25-(04:23:35) - vdi-export success 2017-10-25-(04:23:35) - 5.cmd: /opt/xensource/bin/xe vdi-destroy uuid=11e5de51-40b0-42b3-8eb0-85ef77e34e01 2017-10-25-(04:23:38) - vdi-export end 2017-10-25-(04:23:38) - LARGE FILE > 60G: /mnt/backup/xenserver0/Web-Dev/backup-2017-10-25-(00:10:56)/Web-Dev.vhd : 757G 2017-10-25-(04:23:38) - success_compress: /mnt/backup/xenserver0/Web-Dev/backup-2017-10-25-(00:10:56)/Web-Dev.vhd : 757G 2017-10-25-(04:23:38) - Deleting oldest backup /mnt/backup/xenserver0/Web-Dev/backup-2017-10-24-(00:10:13) 2017-10-25-(04:24:03) - VmBackup vdi-export Web-Dev - Success t:252 2017-10-25-(04:24:03) - vdi-export begin IE9 - Win7 2017-10-25-(04:24:03) - vdi-export - vm_name: IE9 - Win7 max_backups: 1 2017-10-25-(04:24:03) - verify_vm_name: ERROR more than one vm with the name IE9 - Win7 2017-10-25-(04:24:03) - **** vm-export= ***** 2017-10-25-(04:24:03) - * vm-export begin IE10 - Win7 2017-10-25-(04:24:03) - vm-export - vm_name: IE10 - Win7 max_backups: 1 2017-10-25-(04:24:03) - new backup_dir: /mnt/backup/xenserver0/IE10 - Win7/backup-2017-10-25-(04:24:03) 2017-10-25-(04:24:03) - Writing vm config file. 2017-10-25-(04:24:04) - Writing disk info 2017-10-25-(04:24:04) - vbd: OpaqueRef:8a3bbd23-a43c-f1e3-44c0-dddab2e203e5 2017-10-25-(04:24:04) - disk: Virtual Disk - begin 2017-10-25-(04:24:04) - vbd: OpaqueRef:ea0b0694-00ae-be3e-1441-80702419c634 2017-10-25-(04:24:04) - Writing VIF info 2017-10-25-(04:24:04) - Writing VIF: 0 2017-10-25-(04:24:04) - vm-export begin xe command sequence 2017-10-25-(04:24:04) - vm is NOT running 2017-10-25-(04:24:04) - check for prev-vm-snapshot: RESTORE_IE10 - Win7 2017-10-25-(04:24:04) - 1.cmd: /opt/xensource/bin/xe vm-snapshot vm=51222bed-81aa-7b6a-e5f0-726056e23041 new-name-label="RESTORE_IE10 - Win7" 2017-10-25-(04:24:16) - snap-uuid: 47acd09e-9562-c5f9-2a2c-19b83cba3699 2017-10-25-(04:24:16) - 2.cmd: /opt/xensource/bin/xe template-param-set is-a-template=false ha-always-run=false uuid=47acd09e-9562-c5f9-2a2c-19b83cba3699 2017-10-25-(04:24:16) - 3.cmd: /opt/xensource/bin/xe vm-export uuid=47acd09e-9562-c5f9-2a2c-19b83cba3699 filename="/mnt/backup/xenserver0/IE10 - Win7/backup-2017-10-25-(04:24:03)/IE10 - Win7.xva" 2017-10-25-(04:41:48) - Export succeeded 2017-10-25-(04:41:48) - vm-export success 2017-10-25-(04:41:48) - 4.cmd: /opt/xensource/bin/xe vm-uninstall uuid=47acd09e-9562-c5f9-2a2c-19b83cba3699 force=true 2017-10-25-(04:41:50) - The following items are about to be destroyed 2017-10-25-(04:41:50) - VM : 47acd09e-9562-c5f9-2a2c-19b83cba3699 (RESTORE_IE10 - Win7) 2017-10-25-(04:41:50) - VDI: 2fd230ca-6652-4c43-b618-a108f4ccb84a (Virtual Disk) 2017-10-25-(04:41:57) - All objects destroyed 2017-10-25-(04:41:57) - vm-export end 2017-10-25-(04:41:57) - success: /mnt/backup/xenserver0/IE10 - Win7/backup-2017-10-25-(04:24:03)/IE10 - Win7.xva : 12G 2017-10-25-(04:41:57) - Deleting oldest backup /mnt/backup/xenserver0/IE10 - Win7/backup-2017-10-24-(05:09:34) 2017-10-25-(04:41:58) - VmBackup vm-export IE10 - Win7 - Success* t:17 2017-10-25-(04:41:58) - =========================== 2017-10-25-(04:41:58) - Space status: df -Th /mnt/backup/xenserver0/ 2017-10-25-(04:41:58) - Filesystem Type Size Used Avail Use% Mounted on 2017-10-25-(04:41:58) - 192.168.1.19:/mnt/volume1/backup nfs4 1.8T 669G 1.1T 38% /mnt/backup 2017-10-25-(04:41:59) - VmBackup ended - ERRORS DETECTED** - S:2 W:1 E:1

NAUbackup commented 6 years ago

Possibly there is confusion because the VM name contains a space or there are special characters in the name-label field? Is the VM's name in the list using quotes? Did you try deleting the old entry by hand?

Also, which version are you using? There were some wildcard bugs that have been fixed in 3.21. Also, I am going to redo how the metadata are exported for each VM to make it more robust and include all metadata instead of just a few of the pieces.

NAUbackup commented 6 years ago

I have a new test version running that writes all the VM metadata output to a single XML file and handles special character encoding fine. Stay tuned.

NAUbackup commented 6 years ago

Now handled in V3.22.