1 Reply Latest reply on Jun 25, 2014 6:05 AM by Phatsta

    ghettoVCB.work dir doesn't get removed

    Phatsta Enthusiast

      Hello,

       

      Been using ghetto for years now and usually solve any problems om my own, but this time I'm bust. Got a production environment with the latest version of ghetto backing up two VM's to a mounted NAS. It's usually been running fine, except for the occasional out-of-backup-space scenario when you get "Unable to backup *** due to error in VMDK backup", but other than that it's always been okay.

       

      However, 3 weeks ago it crapped out, and upon investigating I noticed that the ghettoVCB.work dir was still there. Thinking it was a one time occurence, I simply removed it and ran the backup again. Same thing happened again, so I started with updating the script, rebooted just in case, that sorta stuff. Still getting the same error though, so after 3 weeks I realise I need some help.

      What happens is that the first backup goes alright, but after the backup is made, upon exiting ghetto, it hangs. And even though it says "Succesfully removed lock directory" it actually has not removed it.

      Currently on following version: "LAST_MODIFIED_DATE=2013_26_11 VERSION=2" which should be the latest. And currently there's 520+GB free space on the NAS, and the total backup volume for the two VM's is about 273GB (at least when looking at older backups).

       

      This is the output of debug:

        • 1. Re: ghettoVCB.work dir doesn't get removed
          Phatsta Enthusiast

          Sorry, couldn't get this pasted because the editor was ***...

           

          2014-06-24 07:35:06 -- info: ============================== ghettoVCB LOG START ==============================

           

          2014-06-24 07:35:06 -- debug: Succesfully acquired lock directory - /tmp/ghettoVCB.work

           

          2014-06-24 07:35:06 -- debug: HOST VERSION: VMware ESXi 5.1.0 build-799733

          2014-06-24 07:35:06 -- debug: HOST LEVEL: VMware ESXi 5.1.0 GA

          2014-06-24 07:35:06 -- debug: HOSTNAME: esxi01.bergstroms.local

           

          2014-06-24 07:35:07 -- info: CONFIG - USING CONFIGURATION FILE = config/bergsrv01

          2014-06-24 07:35:07 -- info: CONFIG - VERSION = 2013_26_11_2

          2014-06-24 07:35:07 -- info: CONFIG - GHETTOVCB_PID = 1307123

          2014-06-24 07:35:07 -- info: CONFIG - VM_BACKUP_VOLUME = /vmfs/volumes/bergnas01

          2014-06-24 07:35:07 -- info: CONFIG - VM_BACKUP_ROTATION_COUNT = 3

          2014-06-24 07:35:07 -- info: CONFIG - VM_BACKUP_DIR_NAMING_CONVENTION = 2014-06-24_07-35-06

          2014-06-24 07:35:07 -- info: CONFIG - DISK_BACKUP_FORMAT = thin

          2014-06-24 07:35:07 -- info: CONFIG - POWER_VM_DOWN_BEFORE_BACKUP = 0

          2014-06-24 07:35:07 -- info: CONFIG - ENABLE_HARD_POWER_OFF = 0

          2014-06-24 07:35:07 -- info: CONFIG - ITER_TO_WAIT_SHUTDOWN = 4

          2014-06-24 07:35:07 -- info: CONFIG - POWER_DOWN_TIMEOUT = 5

          2014-06-24 07:35:07 -- info: CONFIG - SNAPSHOT_TIMEOUT = 15

          2014-06-24 07:35:07 -- info: CONFIG - LOG_LEVEL = debug

          2014-06-24 07:35:07 -- info: CONFIG - BACKUP_LOG_OUTPUT = /tmp/ghettoVCB-2014-06-24_07-35-06-1307123.log

          2014-06-24 07:35:07 -- info: CONFIG - ENABLE_COMPRESSION = 0

          2014-06-24 07:35:07 -- info: CONFIG - VM_SNAPSHOT_MEMORY = 0

          2014-06-24 07:35:07 -- info: CONFIG - VM_SNAPSHOT_QUIESCE = 0

          2014-06-24 07:35:07 -- info: CONFIG - ALLOW_VMS_WITH_SNAPSHOTS_TO_BE_BACKEDUP = 0

          2014-06-24 07:35:07 -- info: CONFIG - VMDK_FILES_TO_BACKUP = bergsrv01.vmdk,bergsrv01_1.vmdk

          2014-06-24 07:35:07 -- info: CONFIG - VM_SHUTDOWN_ORDER =

          2014-06-24 07:35:07 -- info: CONFIG - VM_STARTUP_ORDER =

          2014-06-24 07:35:07 -- info: CONFIG - RSYNC_LINK = 0

          2014-06-24 07:35:07 -- info: CONFIG - EMAIL_LOG = 1

          2014-06-24 07:35:07 -- info: CONFIG - EMAIL_SERVER = smtprelay1.telia.com

          2014-06-24 07:35:07 -- info: CONFIG - EMAIL_SERVER_PORT = 25

          2014-06-24 07:35:07 -- info: CONFIG - EMAIL_DELAY_INTERVAL = 1

          2014-06-24 07:35:07 -- info: CONFIG - EMAIL_FROM = esxibackup@***

          2014-06-24 07:35:07 -- info: CONFIG - EMAIL_TO = itsupport@***

          2014-06-24 07:35:07 -- info: CONFIG - WORKDIR_DEBUG = 0

          2014-06-24 07:35:07 -- info:

          2014-06-24 07:35:11 -- debug: Storage Information before backup:

          2014-06-24 07:35:11 -- debug: SRC_DATASTORE: storage01

          2014-06-24 07:35:11 -- debug: SRC_DATASTORE_CAPACITY: 931.2 GB

          2014-06-24 07:35:11 -- debug: SRC_DATASTORE_FREE: 696.9 GB

          2014-06-24 07:35:11 -- debug: SRC_DATASTORE_BLOCKSIZE: 1

          2014-06-24 07:35:11 -- debug: SRC_DATASTORE_MAX_FILE_SIZE: 256 GB

          2014-06-24 07:35:11 -- debug:

          2014-06-24 07:35:11 -- debug: DST_DATASTORE: bergnas01

          2014-06-24 07:35:11 -- debug: DST_DATASTORE_CAPACITY: 925.4 GB

          2014-06-24 07:35:11 -- debug: DST_DATASTORE_FREE: 521.7 GB

          2014-06-24 07:35:11 -- debug: DST_DATASTORE_BLOCKSIZE: NA

          2014-06-24 07:35:11 -- debug: DST_DATASTORE_MAX_FILE_SIZE: NA

          2014-06-24 07:35:11 -- debug:

          2014-06-24 07:35:11 -- debug: getVMDKs() - /vmfs/volumes/508193bb-3d175eaa-ede6-001517a1b122/bergsrv01/bergsrv01_2.vmdk###930:bergsrv01_1.vmdk###600:bergsrv01.vmdk###250:

          2014-06-24 07:35:12 -- info: Initiate backup for bergsrv01

          2014-06-24 07:35:12 -- info: Creating Snapshot "ghettoVCB-snapshot-2014-06-24" for bergsrv01

          2014-06-24 07:35:15 -- debug: Waiting for snapshot "ghettoVCB-snapshot-2014-06-24" to be created

          2014-06-24 07:35:15 -- debug: Snapshot timeout set to: 900 seconds

          2014-06-24 07:35:16 -- debug: findVMDK() - Searching for VMDK: "/vmfs/volumes/508193bb-3d175eaa-ede6-001517a1b122/bergsrv01/bergsrv01_2.vmdk" to backup

          2014-06-24 07:35:16 -- debug: findVMDK() - Searching for VMDK: "bergsrv01_1.vmdk" to backup

          2014-06-24 07:35:16 -- debug: findVMDK() - Found VMDK! - "bergsrv01_1.vmdk" to backup

          2014-06-24 07:35:16 -- debug: /sbin/vmkfstools -i "/vmfs/volumes/storage01/bergsrv01/bergsrv01_1.vmdk" -a "lsilogic" -d "thin" "/vmfs/volumes/bergnas01/bergsrv01/bergsrv01-2014-06-24_07-35-06/bergsrv01_1.vmdk"

          2014-06-24 12:01:25 -- debug: findVMDK() - Searching for VMDK: "bergsrv01.vmdk" to backup

          2014-06-24 12:01:25 -- debug: findVMDK() - Found VMDK! - "bergsrv01.vmdk" to backup

          2014-06-24 12:01:25 -- debug: /sbin/vmkfstools -i "/vmfs/volumes/storage01/bergsrv01/bergsrv01.vmdk" -a "lsilogic" -d "thin" "/vmfs/volumes/bergnas01/bergsrv01/bergsrv01-2014-06-24_07-35-06/bergsrv01.vmdk"

          2014-06-24 14:21:40 -- info: Removing snapshot from bergsrv01 ...

          2014-06-24 14:21:40 -- info: Backup Duration: 406.47 Minutes

          2014-06-24 14:21:40 -- info: Successfully completed backup for bergsrv01!

           

          2014-06-24 14:21:43 -- debug: Storage Information after backup:

          2014-06-24 14:21:43 -- debug: SRC_DATASTORE: storage01

          2014-06-24 14:21:43 -- debug: SRC_DATASTORE_CAPACITY: 931.2 GB

          2014-06-24 14:21:43 -- debug: SRC_DATASTORE_FREE: 696.9 GB

          2014-06-24 14:21:43 -- debug: SRC_DATASTORE_BLOCKSIZE: 1

          2014-06-24 14:21:43 -- debug: SRC_DATASTORE_MAX_FILE_SIZE: 256 GB

          2014-06-24 14:21:43 -- debug:

          2014-06-24 14:21:43 -- debug: DST_DATASTORE: bergnas01

          2014-06-24 14:21:43 -- debug: DST_DATASTORE_CAPACITY: 925.4 GB

          2014-06-24 14:21:43 -- debug: DST_DATASTORE_FREE: 521.7 GB

          2014-06-24 14:21:43 -- debug: DST_DATASTORE_BLOCKSIZE: NA

          2014-06-24 14:21:43 -- debug: DST_DATASTORE_MAX_FILE_SIZE: NA

          2014-06-24 14:21:43 -- debug:

          2014-06-24 14:21:43 -- info: CONFIG - USING CONFIGURATION FILE = config/bergsrv02

          2014-06-24 14:21:43 -- info: CONFIG - VERSION = 2013_26_11_2

          2014-06-24 14:21:43 -- info: CONFIG - GHETTOVCB_PID = 1307123

          2014-06-24 14:21:43 -- info: CONFIG - VM_BACKUP_VOLUME = /vmfs/volumes/bergnas01

          2014-06-24 14:21:43 -- info: CONFIG - VM_BACKUP_ROTATION_COUNT = 3

          2014-06-24 14:21:43 -- info: CONFIG - VM_BACKUP_DIR_NAMING_CONVENTION = 2014-06-24_07-35-06

          2014-06-24 14:21:43 -- info: CONFIG - DISK_BACKUP_FORMAT = thin

          2014-06-24 14:21:43 -- info: CONFIG - POWER_VM_DOWN_BEFORE_BACKUP = 0

          2014-06-24 14:21:43 -- info: CONFIG - ENABLE_HARD_POWER_OFF = 0

          2014-06-24 14:21:43 -- info: CONFIG - ITER_TO_WAIT_SHUTDOWN = 4

          2014-06-24 14:21:43 -- info: CONFIG - POWER_DOWN_TIMEOUT = 5

          2014-06-24 14:21:43 -- info: CONFIG - SNAPSHOT_TIMEOUT = 15

          2014-06-24 14:21:43 -- info: CONFIG - LOG_LEVEL = debug

          2014-06-24 14:21:44 -- info: CONFIG - BACKUP_LOG_OUTPUT = /tmp/ghettoVCB-2014-06-24_07-35-06-1307123.log

          2014-06-24 14:21:44 -- info: CONFIG - ENABLE_COMPRESSION = 0

          2014-06-24 14:21:44 -- info: CONFIG - VM_SNAPSHOT_MEMORY = 0

          2014-06-24 14:21:44 -- info: CONFIG - VM_SNAPSHOT_QUIESCE = 0

          2014-06-24 14:21:44 -- info: CONFIG - ALLOW_VMS_WITH_SNAPSHOTS_TO_BE_BACKEDUP = 0

          2014-06-24 14:21:44 -- info: CONFIG - VMDK_FILES_TO_BACKUP = bergsrv02.vmdk,bergsrv02_1.vmdk

          2014-06-24 14:21:44 -- info: CONFIG - VM_SHUTDOWN_ORDER =

          2014-06-24 14:21:44 -- info: CONFIG - VM_STARTUP_ORDER =

          2014-06-24 14:21:44 -- info: CONFIG - RSYNC_LINK = 0

          2014-06-24 14:21:44 -- info: CONFIG - EMAIL_LOG = 1

          2014-06-24 14:21:44 -- info: CONFIG - EMAIL_SERVER = smtprelay1.telia.com

          2014-06-24 14:21:44 -- info: CONFIG - EMAIL_SERVER_PORT = 25

          2014-06-24 14:21:44 -- info: CONFIG - EMAIL_DELAY_INTERVAL = 1

          2014-06-24 14:21:44 -- info: CONFIG - EMAIL_FROM = esxibackup@***

          2014-06-24 14:21:44 -- info: CONFIG - EMAIL_TO = itsupport@***

          2014-06-24 14:21:44 -- info: CONFIG - WORKDIR_DEBUG = 0

          2014-06-24 14:21:44 -- info:

          2014-06-24 14:21:47 -- debug: Storage Information before backup:

          2014-06-24 14:21:47 -- debug: SRC_DATASTORE: datastore1

          2014-06-24 14:21:47 -- debug: SRC_DATASTORE_CAPACITY: 926.5 GB

          2014-06-24 14:21:47 -- debug: SRC_DATASTORE_FREE: 869.7 GB

          2014-06-24 14:21:47 -- debug: SRC_DATASTORE_BLOCKSIZE: 1

          2014-06-24 14:21:47 -- debug: SRC_DATASTORE_MAX_FILE_SIZE: 256 GB

          2014-06-24 14:21:47 -- debug:

          2014-06-24 14:21:47 -- debug: DST_DATASTORE: bergnas01

          2014-06-24 14:21:47 -- debug: DST_DATASTORE_CAPACITY: 925.4 GB

          2014-06-24 14:21:47 -- debug: DST_DATASTORE_FREE: 521.7 GB

          2014-06-24 14:21:47 -- debug: DST_DATASTORE_BLOCKSIZE: NA

          2014-06-24 14:21:47 -- debug: DST_DATASTORE_MAX_FILE_SIZE: NA

          2014-06-24 14:21:47 -- debug:

          2014-06-24 14:21:48 -- debug: getVMDKs() - /vmfs/volumes/521721a4-874cb338-15b5-001517a1b122/bergsrv02/bergsrv02_2.vmdk###930:bergsrv02_1.vmdk###900:bergsrv02.vmdk###60:

          2014-06-24 14:21:48 -- info: Initiate backup for bergsrv02

          2014-06-24 14:21:48 -- info: Creating Snapshot "ghettoVCB-snapshot-2014-06-24" for bergsrv02

          2014-06-24 14:21:53 -- debug: Waiting for snapshot "ghettoVCB-snapshot-2014-06-24" to be created

          2014-06-24 14:21:53 -- debug: Snapshot timeout set to: 900 seconds

          2014-06-24 14:21:54 -- debug: findVMDK() - Searching for VMDK: "/vmfs/volumes/521721a4-874cb338-15b5-001517a1b122/bergsrv02/bergsrv02_2.vmdk" to backup

          2014-06-24 14:21:54 -- debug: findVMDK() - Searching for VMDK: "bergsrv02_1.vmdk" to backup

          2014-06-24 14:21:54 -- debug: findVMDK() - Found VMDK! - "bergsrv02_1.vmdk" to backup

          2014-06-24 14:21:54 -- debug: /sbin/vmkfstools -i "/vmfs/volumes/datastore1/bergsrv02/bergsrv02_1.vmdk" -a "lsilogic" -d "thin" "/vmfs/volumes/bergnas01/bergsrv02/bergsrv02-2014-06-24_07-35-06/bergsrv02_1.vmdk"

          2014-06-24 15:11:02 -- debug: findVMDK() - Searching for VMDK: "bergsrv02.vmdk" to backup

          2014-06-24 15:11:02 -- debug: findVMDK() - Found VMDK! - "bergsrv02.vmdk" to backup

          2014-06-24 15:11:02 -- debug: /sbin/vmkfstools -i "/vmfs/volumes/datastore1/bergsrv02/bergsrv02.vmdk" -a "lsilogic" -d "thin" "/vmfs/volumes/bergnas01/bergsrv02/bergsrv02-2014-06-24_07-35-06/bergsrv02.vmdk"

          2014-06-24 15:55:21 -- info: Removing snapshot from bergsrv02 ...

          2014-06-24 15:55:21 -- info: Backup Duration: 93.55 Minutes

          2014-06-24 15:55:21 -- info: Successfully completed backup for bergsrv02!

           

          2014-06-24 15:55:24 -- debug: Storage Information after backup:

          2014-06-24 15:55:24 -- debug: SRC_DATASTORE: datastore1

          2014-06-24 15:55:24 -- debug: SRC_DATASTORE_CAPACITY: 926.5 GB

          2014-06-24 15:55:24 -- debug: SRC_DATASTORE_FREE: 869.7 GB

          2014-06-24 15:55:24 -- debug: SRC_DATASTORE_BLOCKSIZE: 1

          2014-06-24 15:55:24 -- debug: SRC_DATASTORE_MAX_FILE_SIZE: 256 GB

          2014-06-24 15:55:24 -- debug:

          2014-06-24 15:55:24 -- debug: DST_DATASTORE: bergnas01

          2014-06-24 15:55:24 -- debug: DST_DATASTORE_CAPACITY: 925.4 GB

          2014-06-24 15:55:24 -- debug: DST_DATASTORE_FREE: 521.7 GB

          2014-06-24 15:55:24 -- debug: DST_DATASTORE_BLOCKSIZE: NA

          2014-06-24 15:55:24 -- debug: DST_DATASTORE_MAX_FILE_SIZE: NA

          2014-06-24 15:55:25 -- debug:

          2014-06-24 15:55:25 -- info: ###### Final status: All VMs backed up OK! ######

           

          2014-06-24 15:55:25 -- debug: Succesfully removed lock directory - /tmp/ghettoVCB.work

           

          2014-06-24 15:55:25 -- info: ============================== ghettoVCB LOG END ================================