[SOLVED] proxmox-backup-client in docker: Subsequential backups never reuse data?

[t0mc@]

Hi everybody,

I have an older Debian Stretch Server which can't simply be upgraded to a newer Debian Version. There I want to use proxmox-backup-client for backing up some files to a running PBS. As proxmox-backup-client can't be installed on Stretch cause of missing dependencies I gave a dockerized client a try and used this quick and dirty Dockerfile for creating such an image:

FROM debian:bullseye-slim
RUN apt update && apt install -y wget && wget https://enterprise.proxmox.com/debian/proxmox-release-bullseye.gpg -O /etc/apt/trusted.gpg.d/proxmox-release-bullseye.gpg; \
    echo "deb http://download.proxmox.com/debian/pbs-client bullseye main" >> /etc/apt/sources.list.d/pbs.list; \
    apt update && apt install -y proxmox-backup-client

For testing things out I started and entered a container from this image:

docker run --rm -it --hostname $(hostname) -v /home:/home:ro -v /opt/pbs/.cache:/root/.cache --env-file /opt/pbs/env pbs-client bash

Docker Arguments:
--hostname... -> So that the Container has the same Hostname than the machine and therefore the backup has the correct group name in PBS
-v /home... -> Mounted the Filesystem from which backups should be taken in readonly mode
-v /opt/pbs/.cache... -> Persist files in /root/.cache that proxmox-backup-client creates (not sure, if it is important)
--env-file...-> Contains Env - Vars like PBS_REPOSITORY, TZ a.s.o.

In the container I started a Backup twice:

root@ContainerHostName:/home# proxmox-backup-client backup backuptest.pxar:/home/backuptest
Starting backup: host/ContainerHostName/2022-04-01T16:03:17Z
Client name: ContainerHostName
Starting backup protocol: Fri Apr  1 18:03:17 2022
No previous manifest available.
Upload directory '/home/backuptest' to 'RepositoryURL' as backuptest.pxar.didx
backuptest.pxar: had to backup 623.076 MiB of 623.076 MiB (compressed 479.674 MiB) in 5.85s
backuptest.pxar: average backup speed: 106.521 MiB/s
Uploaded backup catalog (110.466 KiB)
Duration: 5.90s
End Time: Fri Apr  1 18:03:22 2022

root@ContainerHostName:/home# proxmox-backup-client backup backuptest.pxar:/home/backuptest
Starting backup: host/ContainerHostName/2022-04-01T16:03:33Z
Client name: ContainerHostName
Starting backup protocol: Fri Apr  1 18:03:33 2022
Downloading previous manifest (Fri Apr  1 18:03:17 2022)
Upload directory '/home/backuptest' to 'RepositoryURL' as backuptest.pxar.didx
backuptest.pxar: had to backup 623.076 MiB of 623.076 MiB (compressed 479.674 MiB) in 5.98s
backuptest.pxar: average backup speed: 104.217 MiB/s
Uploaded backup catalog (110.466 KiB)
Duration: 6.02s
End Time: Fri Apr  1 18:03:39 2022

In the second backup I'm especially confused about this line:
backuptest.pxar: had to backup 623.076 MiB of 623.076 MiB (compressed 479.674 MiB) in 5.98s

Why? This has to be "0 of 623.076 MiB" correctly as no bit has changed after the first backup a few seconds before, hasn't it?

For verifiying I did a second test on another machine where proxmox-backup-client is normally installed:

root@AnotherMachine:/mnt/data# proxmox-backup-client backup test.pxar:/mnt/data/backuptest
Starting backup: host/AnotherMachine/2022-04-01T15:59:54Z
Client name: AnotherMachine
Starting backup protocol: Fri Apr  1 17:59:54 2022
No previous manifest available.
Upload directory '/mnt/data/backuptest' to 'RepositoryURL' as test.pxar.didx
test.pxar: had to backup 620.983 MiB of 625.614 MiB (compressed 478.827 MiB) in 12.35s
test.pxar: average backup speed: 50.28 MiB/s
test.pxar: backup was done incrementally, reused 4.63 MiB (0.7%)
Uploaded backup catalog (110.521 KiB)
Duration: 12.54s
End Time: Fri Apr  1 18:00:07 2022

root@AnotherMachine:/mnt/data# proxmox-backup-client backup test.pxar:/mnt/data/backuptest
Starting backup: host/AnotherMachine/2022-04-01T16:00:59Z
Client name: AnotherMachine
Starting backup protocol: Fri Apr  1 18:00:59 2022
Downloading previous manifest (Fri Apr  1 17:59:54 2022)
Upload directory '/mnt/data/backuptest' to 'RepositoryURL' as test.pxar.didx
test.pxar: had to backup 0 B of 625.614 MiB (compressed 0 B) in 5.98s
test.pxar: average backup speed: 0 B/s
test.pxar: backup was done incrementally, reused 625.614 MiB (100.0%)
Uploaded backup catalog (110.521 KiB)
Duration: 6.35s
End Time: Fri Apr  1 18:01:06 2022

Here the output of the second backup is as expected: "had to backup 0 B of 625.614 MiB".
And what is more confusing and is another hint IMHO:
In these backups there are lines like "backup was done incrementally, reused..." (even when running the first time, which I also don't understand). These lines are completely missing in the docker-based client.

Any idea what I'm doing wrong in the docker-way?

Thx in advance

 

[dcsapak]

Hi,

this does indeed look weird and unexpected...

Why? This has to be "0 of 623.076 MiB" correctly as no bit has changed after the first backup a few seconds before, hasn't it?

maybe the metadata (mtime, etc) changed? if that happens and the files are not too big, the resulting pxar files and resulting chunks could be very different and not deduplicatable...
you could check by downloading both pxar files and do a binary diff with 'cmp'

(though i find it unlikely that with only the metadata change not a single chunk could be reused)

And what is more confusing and is another hint IMHO:
In these backups there are lines like "backup was done incrementally, reused..." (even when running the first time, which I also don't understand). These lines are completely missing in the docker-based client.

this is only printed when at least one chunk is reused

Any idea what I'm doing wrong in the docker-way?

not really, how does your docker setup look like? (version, etc.)

 

[t0mc@]

Hi,

this does indeed look weird and unexpected...

maybe the metadata (mtime, etc) changed? if that happens and the files are not too big, the resulting pxar files and resulting chunks could be very different and not deduplicatable...

If this where the case I would really wonder what would have changed these metadata a few seconds after the first backup:
First Backup start Time: 2022-04-01T16:03:17Z
Second Backup start time: 2022-04-01T16:03:33Z

you could check by downloading both pxar files and do a binary diff with 'cmp'

(though i find it unlikely that with only the metadata change not a single chunk could be reused)

I downloaded the two backuptest.pxar(.didx) files via the PBS Web GUI and compared them. These are the results:

user@clientmachine:~/pbs$ ls -al
insgesamt 1276112
drwxrwxr-x   2 user user      4096 Apr  4 11:40 .
drwxr-xr-x 194 user user     32768 Apr  4 11:38 ..
-rw-rw-r--   1 user user 653342108 Apr  4 11:39 backuptest1.pxar
-rw-rw-r--   1 user user 653342108 Apr  4 11:40 backuptest2.pxar

--> Identical in size (Yes, I'm really sure I downloaded from the two different backups )

user@clientmachine:~/pbs$ cmp backuptest1.pxar backuptest2.pxar 
user@clientmachine:~/pbs$ md5sum backuptest1.pxar 
fdb11e84fdb805a4fce9e3e75c69d7bb  backuptest1.pxar
user@clientmachine:~/pbs$ md5sum backuptest2.pxar 
fdb11e84fdb805a4fce9e3e75c69d7bb  backuptest2.pxar
user@clientmachine:~/pbs$

--> "cmp" gave no output, so they are binary identical
--> Even md5sums are identical

this is only printed when at least one chunk is reused

OK, which is an additional clue that the second backup looks like a complete new one.

not really, how does your docker setup look like? (version, etc.)

Docker was installed from the standard Debian Stretch Repo:

docker -v
Docker version 18.09.7, build 2d0083d

What else do u need to know?

 

[dcsapak]

If this where the case I would really wonder what would have changed these metadata a few seconds after the first backup:

my guess was that the docker bindmount (or however it mount the dir into the container) does something weird but it seems it doesn't

--> Identical in size (Yes, I'm really sure I downloaded from the two different backups )

--> "cmp" gave no output, so they are binary identical
--> Even md5sums are identical

ok now it gets really weird, since if they are the same, that means the chunks would have to be the same...
you could verify that by going into the pbs and compare the .didx files for those two pxar files, they are found in /path/to/datastore/host/HOSTNAME/BACKUPID/test.pxar.didx

if the data is identical, those should too be identical

Docker was installed from the standard Debian Stretch Repo:

ok thx, i'll try to reproduce it here...

 

[dcsapak]

ok i see why it does not work:

the fs inside the container is an 'overlayfs' for '/' (including /tmp)
when downloading the fidx/didx files from the previous backup, we save it to a file in /tmp with the 'O_TMPFILE' creation option, which is not supported in overlayfs
then, we silently ignore that error and continue. now we of course have to upload everything again since we don't know what was in the backup

it worked when i made /tmp a tmpfs in the container '--tmpfs /tmp' to the docker command

i'll send a patch to print at least an error when we could not download the manifest, else the output is indeed rather confusing

 

[t0mc@]

Indeed, with --tmpfs option in the docker command it looks MUCH better

root@container:/# proxmox-backup-client backup backuptest.pxar:/home/backuptest
Starting backup: host/container/2022-04-04T12:21:40Z
Client name: container
Starting backup protocol: Mon Apr  4 12:21:40 2022
No previous manifest available.
Upload directory '/home/backuptest' to 'RepositoryURL' as backuptest.pxar.didx
backuptest.pxar: had to backup 623.076 MiB of 623.076 MiB (compressed 479.674 MiB) in 5.79s
backuptest.pxar: average backup speed: 107.59 MiB/s
Uploaded backup catalog (110.466 KiB)
Duration: 5.87s
End Time: Mon Apr  4 12:21:46 2022
root@container:/# proxmox-backup-client backup backuptest.pxar:/home/backuptest
Starting backup: host/container/2022-04-04T12:21:49Z
Client name: container
Starting backup protocol: Mon Apr  4 12:21:49 2022
Downloading previous manifest (Mon Apr  4 12:21:40 2022)
Upload directory '/home/backuptest' to 'RepositoryURL' as backuptest.pxar.didx
backuptest.pxar: had to backup 0 B of 623.076 MiB (compressed 0 B) in 2.95s
backuptest.pxar: average backup speed: 0 B/s
backuptest.pxar: backup was done incrementally, reused 623.076 MiB (100.0%)
Uploaded backup catalog (110.466 KiB)
Duration: 2.99s
End Time: Mon Apr  4 12:21:52 2022
root@container:/#

Thx a lot, good Job!