Backup errors

[Erwin123]

I noticed today I didn't receive a message from the backup of the main node.
I looked at the logfiles and see this for every file (log size 12MB)

---cut and paste---
Dec 02 04:10:57 INFO: tar: ./var/qmail/queue: Warning: Cannot close: Bad file descriptor
Dec 02 04:10:57 INFO: tar: ./var/qmail/control: Warning: Cannot savedir: Input/output error
Dec 02 04:10:57 INFO: tar: ./var/qmail/control: Warning: Cannot close: Bad file descriptor
Dec 02 04:10:57 INFO: tar: ./var/qmail/alias: Warning: Cannot savedir: Input/output error
Dec 02 04:10:57 INFO: tar: ./var/qmail/alias: Warning: Cannot close: Bad file descriptor
Dec 02 04:10:57 INFO: tar: ./var/local: Warning: Cannot savedir: Input/output error
Dec 02 04:10:57 INFO: tar: ./var/local: Warning: Cannot close: Bad file descriptor
Dec 02 04:10:57 INFO: tar: ./var/log: Warning: Cannot savedir: Input/output error
Dec 02 04:10:57 INFO: tar: ./var/log: Warning: Cannot close: Bad file descriptor
Dec 02 04:10:57 INFO: tar: ./var/db: Warning: Cannot savedir: Input/output error
Dec 02 04:10:57 INFO: tar: ./var/db: Warning: Cannot close: Bad file descriptor
Dec 02 04:10:57 INFO: tar: ./aquota.group: Warning: Cannot stat: No such file or directory
Dec 02 04:10:57 INFO: tar: ./sbin: Warning: Cannot savedir: Input/output error
Dec 02 04:10:57 INFO: tar: ./sbin: Warning: Cannot close: Bad file descriptor
Dec 02 04:10:57 INFO: tar: ./home: Warning: Cannot savedir: Input/output error
Dec 02 04:10:57 INFO: tar: ./home: Warning: Cannot close: Bad file descriptor
Dec 02 04:10:57 INFO: Total bytes written: 1067530240 (1019MiB, 4.4MiB/s)
Dec 02 04:10:57 INFO: file size 1018MB
Dec 02 04:11:34 INFO: Logical volume "vzsnap" successfully removed
Dec 02 04:11:34 INFO: Finished Backup of VM 107 (00:11:42)

There enough space left in the root partition (48Gig)
An idea?

Thanks Erwin

 

[dietmar]

Maybe the LVM snapshot run out of space. By default we allocate 1GB for the snapshot. You can use the '--size' parameter of vzdump to increase that.

- Dietmar

 

[Erwin123]

I've set the backups in the CP. Where do I enter this --size parameter?
And can you give an example of what a good value would be?

Thanks.

 

[dietmar]

You need to create the file /etc/vzdump.conf

And add the following line:

size: 2048

see 'man vzdump'

- Dietmar

 

[Erwin123]

Okay, thanks!

 

[Erwin123]

The backup ran successful today.
I do however get a lot of these errors:

tar: ./home/httpd/vhosts/some-domain.nl/httpdocs/Leagues/Assets/..(6: Warning: Cannot stat: No such file or directory

Are they something that need to be solved?

Thanks.

 

[dietmar]

tar: ./home/httpd/vhosts/some-domain.nl/httpdocs/Leagues/Assets/..(6: Warning: Cannot stat: No such file or directory

Are they something that need to be solved?

Yes, your backup does not include those files! Please can you post the complete log?

 

[Erwin123]

I see today I only had one of those errors. yesterday my log was full of them.

The log today:

Dec 03 05:09:01 INFO: Starting Backup of VM 107 (openvz)
Dec 03 05:09:01 INFO: status = CTID 107 exist mounted running
Dec 03 05:09:01 INFO: creating lvm snapshot of /dev/mapper/pve-data ('/dev/pve/vzsnap')
Dec 03 05:09:01 INFO: Logical volume "vzsnap" created
Dec 03 05:09:01 INFO: mounting lvm snapshot
Dec 03 05:09:07 INFO: creating archive '/backup/vzdump-107.dat' (/mnt/vzsnap/private/107)
Dec 03 07:12:00 INFO: tar: ./home/httpd/vhosts/domainname.nl/httpdocs/Leagues/Assets/..(6: Warning: Cannot stat: No such file or directory
Dec 03 07:41:06 INFO: Total bytes written: 18973675520 (18GiB, 2.1MiB/s)
Dec 03 07:41:06 INFO: file size 17.67GB
Dec 03 07:41:10 INFO: Logical volume "vzsnap" successfully removed
Dec 03 07:41:10 INFO: Finished Backup of VM 107 (02:32:09)

The log yesterday was 17MB so I better not paste that here. it just mentions every file with "Warning: Cannot stat: No such file or directory"
I imagine they were probably caused by the problem mentioned in my first post.

 

[dietmar]

Why is the backup that slow (2.1MiB/s) - slow hard disks?

 

[Erwin123]

Its two sata disks in raid 1. They might be a bit too heavy loaded:

node1:/backup# pveperf
CPU BOGOMIPS: 16003.85
REGEX/SECOND: 730675
HD SIZE: 94.49 GB (/dev/pve/root)
BUFFERED READS: 30.85 MB/sec
AVERAGE SEEK TIME: 25.74 ms
FSYNCS/SECOND: 95.66
DNS EXT: 42.92 ms
DNS INT: 24.53 ms (localhost)

 

[dietmar]

Wow, this is really slow. Is this test done when the server was under high load? If not, you should consider using faster disks.

- Dietmar

 

[Erwin123]

I have a 8 disk raid-10 ready on my desk (Read 450 MB/S) but have to wait until the weekend before I dare to move the containers...

The server has a total of 225 websites spread over two containers (CentOs, Plesk).
We used to run that on a sinlge FreeBSD server with the same disks but less ram and CPU. It only occured to us recently that IO's are the bottleneck instead of CPU and RAM

 

[dietmar]

And hopefully you have a battery backed cache and enabled write back mode on your new RAID controller. Disabling the Disk cache (the cache inside the HD) is also recommended for most RAID controllers.

 

[Erwin123]

It has a Areca ARC1222 adapter with battery.
I just took a look at the configuration and have the following options:

HDD Read Ahead Cache: Enable, Disable Maxtor, Disable

Volume Data Read Ahead: Normal, Agressive, Conservative, Disable

Disk write Cache mode: Enabled, Disabled

It also has an option: Activate incomplete Raid when power on, wich is disabled (that seems wrong to me?).

Thanks for your advise.

 

[dietmar]

sorry, I do not know that controller - please consult the controller manual ;-)

 

[Erwin123]

Today I've got a 167MB logfile filled with these messages:

Dec 04 03:25:24 INFO: Starting Backup of VM 107 (openvz)
Dec 04 03:25:24 INFO: status = CTID 107 exist mounted running
Dec 04 03:25:39 INFO: creating lvm snapshot of /dev/mapper/pve-data ('/dev/pve/vzsnap')
Dec 04 03:25:49 INFO: Logical volume "vzsnap" created
Dec 04 03:25:49 INFO: mounting lvm snapshot
Dec 04 03:35:41 INFO: creating archive '/backup/vzdump-107.dat' (/mnt/vzsnap/private/107)
Dec 04 03:55:05 INFO: find: ./home/httpd/vhosts/domain.nl/httpsdocs/img: No such file or directory
Dec 04 03:55:05 INFO: find: ./home/httpd/vhosts/domain.nl/httpsdocs/plesk-stat: Input/output error
Dec 04 03:55:05 INFO: find: ./home/httpd/vhosts/domain.nl/httpsdocs/picture_library: Input/output error
Dec 04 03:55:05 INFO: find: ./home/httpd/vhosts/domain.nl/httpdocs: No such file or directory
Dec 04 03:55:05 INFO: find: ./home/httpd/vhosts/domein.nl/conf: Input/output error
Dec 04 03:55:05 INFO: find: ./home/httpd/vhosts/domein.nl/bin: Input/output error
-----etc...
Dec 04 03:55:06 INFO: tar: ./tmp/dompdf_img_XK0wTo: Warning: Cannot stat: No such file or directory
Dec 04 03:55:06 INFO: tar: ./tmp/dompdf_img_nAZp4w: Warning: Cannot stat: No such file or directory
Dec 04 03:55:06 INFO: tar: ./tmp/dompdf_img_X4LnJ4: Warning: Cannot stat: No such file or directory
Dec 04 03:55:06 INFO: tar: ./tmp/dompdf_img_5gNG39: Warning: Cannot stat: No such file or directory
Dec 04 03:55:06 INFO: tar: ./tmp/impattIsvYQH: Warning: Cannot stat: No such file or directory
---etc...
Dec 04 03:55:06 INFO: tar: ./etc/krb5.conf: Warning: Cannot stat: No such file or directory
Dec 04 03:55:06 INFO: tar: ./etc/syslog.conf: Warning: Read error at byte 0, while reading 712 bytes: Input/output error
Dec 04 03:55:06 INFO: tar: ./etc/openldap/ldap.conf: Warning: Cannot stat: No such file or directory
Dec 04 03:55:06 INFO: tar: ./etc/samba/smbusers: Warning: Cannot stat: No such file or directory
Dec 04 03:55:06 INFO: tar: ./etc/samba/lmhosts: Warning: Cannot stat: No such file or directory
Dec 04 03:55:06 INFO: tar: ./etc/samba/smb.conf: Warning: Cannot stat: No such file or directory
Dec 04 03:55:06 INFO: tar: ./etc/updatedb.conf: Warning: Read error at byte 0, while reading 127 bytes: Input/output error
Dec 04 03:55:06 INFO: tar: ./etc/mailman/sitelist.cfg: Warning: Cannot stat: No such file or directory
Dec 04 03:55:06 INFO: tar: ./etc/selinux/semanage.conf: Warning: Cannot stat: No such file or directory
etc...

The backup of this container started at 03:25 and the last line is written at 04:03.

 

[dietmar]

Are there some hints in the syslog? And you really increased the size of the snapshot? During backup, you can see the snapshot size/usage with the following command:

# lvs

Please try to observe that.

- Dietmar

 

[Erwin123]

I feel stupid.
I check the vzdump.conf file as you say and for some reason it says:
size: size: 2048

No idea how that happened, but I guess that must be it.
I'll be back tomorrow with the results

 

[Erwin123]

Backup succeded, but it took awfully long:

103: Dec 05 01:00:02 INFO: Starting Backup of VM 103 (openvz)
103: Dec 05 01:00:02 INFO: status = CTID 103 exist mounted running
103: Dec 05 01:00:02 INFO: creating lvm snapshot of /dev/mapper/pve-data ('/dev/pve/vzsnap')
103: Dec 05 01:00:03 INFO: Logical volume "vzsnap" created
103: Dec 05 01:00:03 INFO: mounting lvm snapshot
103: Dec 05 01:00:06 INFO: creating archive '/backup/vzdump-103.dat' (/mnt/vzsnap/private/103)
103: Dec 05 03:33:55 INFO: Total bytes written: 19716720640 (19GiB, 2.1MiB/s)
103: Dec 05 03:33:55 INFO: file size 18.36GB
103: Dec 05 03:34:13 INFO: Logical volume "vzsnap" successfully removed
103: Dec 05 03:34:13 INFO: Finished Backup of VM 103 (02:34:11)

107: Dec 05 03:34:14 INFO: Starting Backup of VM 107 (openvz)
107: Dec 05 03:34:14 INFO: status = CTID 107 exist mounted running
107: Dec 05 03:34:14 INFO: creating lvm snapshot of /dev/mapper/pve-data ('/dev/pve/vzsnap')
107: Dec 05 03:34:14 INFO: Logical volume "vzsnap" created
107: Dec 05 03:34:14 INFO: mounting lvm snapshot
107: Dec 05 03:34:16 INFO: creating archive '/backup/vzdump-107.dat' (/mnt/vzsnap/private/107)
107: Dec 05 06:12:06 INFO: tar: ./home/httpd/vhosts/domain.nl/httpdocs/Leagues/Assets/..(6: Warning: Cannot stat: No such file or directory
107: Dec 05 07:05:10 INFO: Total bytes written: 19878205440 (19GiB, 1.6MiB/s)
107: Dec 05 07:05:10 INFO: file size 18.51GB
107: Dec 05 07:05:16 INFO: Logical volume "vzsnap" successfully removed
107: Dec 05 07:05:16 INFO: Finished Backup of VM 107 (03:31:03)

 

[Erwin123]

And today it failed again

The log is filled with these messages:

Dec 06 03:42:22 INFO: Starting Backup of VM 107 (openvz)
Dec 06 03:42:22 INFO: status = CTID 107 exist mounted running
Dec 06 03:42:22 INFO: creating lvm snapshot of /dev/mapper/pve-data ('/dev/pve/vzsnap')
Dec 06 03:42:22 INFO: Logical volume "vzsnap" created
Dec 06 03:42:22 INFO: mounting lvm snapshot
Dec 06 03:42:26 INFO: creating archive '/backup/vzdump-107.dat' (/mnt/vzsnap/private/107)
Dec 06 05:01:25 INFO: tar: ./var/qmail/mailnames/domain.nl/name/Maildir/new/1214832840.36741.admin18.123xs.com: Warning: Read error at byte 0, while readi
ng 1010 bytes: Input/output error
etc...

it ends:

Dec 06 05:03:48 INFO: tar: ./home/httpd/vhosts/anotherdomein.nl/private/README.txt: Warning: Cannot stat: No such file or directory
Dec 06 05:03:48 INFO: tar: ./home/httpd/vhosts/anotherdomain.nl/subdomains: Warning: Cannot stat: No such file or directory
Dec 06 05:03:48 INFO: Total bytes written: 6286766080 (5.9GiB, 1.4MiB/s)
Dec 06 05:03:48 INFO: file size 5.86GB
Dec 06 05:08:11 INFO: Logical volume "vzsnap" successfully removed
Dec 06 05:08:11 INFO: Finished Backup of VM 107 (01:25:49)

The logfile is 157MB big, the actual backup near 6GB. It should be 20GB.
I hope you can shed some light on it, because it scares me to death not to have a decent backup.