Re: dar_manager - incremental backups and removed file

On Sunday, 21 April 2024 21:28:48 CEST Denis Corbin wrote:
> On 20/04/2024 15:23, Joost Roeleveld via Dar-support wrote:
> 
[...]
> 
> >   Timestamp read accuracy : 1 nanosecond
> >   Timestamp write accuracy : 1 nanosecond
> 
> this is above the info I wanted to check and this is not what I 
> expected, but OK. The problem seen is not caused by the way dar has been 
> compiled and seems to read dates from the filesystem the same manner
> over the time, I mean it has always read date from the fields of the 
> system "struct stat" returned by lstat() system call:
> - stat::st_atim.tv_sec
> - stat::st_mtim.tv_sec
> - stat::st_ctim.tv_sec
> 
> as implemented in src/libdar/filesystem_hard_link_read.cpp
> 
> [...]
> 
> > 
> >> Have you recently recompiled or upgraded the dar binary used here to 
> >> make backups on that host?
> 
> Here is why I ask, I'll take just the usr/share/fonts/hack/.uuid file to 
> illustrate:
> 
> [Sorry for the ugly formated output... too wide to fit in email]
> 
> # dar -l MNGR_20240301T000001_san1__zdata_os_services_binhost_root -g
> usr/share/fonts/hack -afdd
> Warning: using insecure memory!
> [Data ][D][ EA  ][FSA][Compr][S]| Permission | User  | Group | Size    |
>           Date                 |    filename
> --------------------------------+------------+-------+-------+---------+----
> ---------------------------+------------
 [InRef][-]       [-L-][  70%][ ] 
> drwxr-xr-x   root     root    5 Gio Mon Jul  1 11:34:26 2019 + 370501096 ns
> usr
> [InRef][-]       [-L-][  65%][ ]  drwxr-xr-x   root     root    872 Mio
> Mon Feb 19 17:56:59 2024 + 297538137 ns usr/share
> [InRef][-]       [-L-][  48%][ ]  drwxr-xr-x   root     root    182 Mio
> Thu Jun  3 15:32:10 2021 + 211378 us    usr/share/fonts
> [InRef][-]       [-L-][   0%][ ]  drwxr-xr-x   root     root    36 o
> Thu Jun  3 15:32:10 2021 + 301378 us    usr/share/fonts/hack
> [InRef][ ]       [-L-][-----][ ]  -rw-r--r--   root     root    36 o
> Thu Jun  3 15:32:10 2021 + 301378785 ns usr/share/fonts/hack/.uuid
> 
>  From the above output of the oldest archive, all dates have nanosecond 
> precision [the -afdd option has been added to display *F*ully *D*etailed 
> *D*ates. This option will be available with release 2.8.0 for dar and 
> dar_manager]
> 
> 
> # dar -l MNGR_20240401T000002_san1__zdata_os_services_binhost_root -g
> usr/share/fonts/hack -afdd
> Warning: using insecure memory!
> [Data ][D][ EA  ][FSA][Compr][S]| Permission | User  | Group | Size    |
>           Date                 |    filename
> --------------------------------+------------+-------+-------+---------+----
> ---------------------------+------------
 [InRef][-]       [-L-][  71%][ ] 
> drwxr-xr-x   root     root    4 Gio Thu Mar 28 10:57:11 2024 + 379415752 ns
> usr
> [InRef][-]       [-L-][  66%][ ]  drwxr-xr-x   root     root    832 Mio
> Thu Mar 28 07:53:02 2024 + 534986022 ns usr/share
> [     ][-]       [-l-][  48%][ ]  drwxr-xr-x   root     root    182 Mio
> Thu Jun  3 15:32:10 2021 + 211378 us    usr/share/fonts
> [     ][-]       [-l-][     ][ ]  drwxr-xr-x   root     root    0
> Thu Jun  3 15:32:10 2021 + 301378 us    usr/share/fonts/hack
> [     ][ ]       [-l-][-----][ ]  -rw-r--r--   root     root    36 o
> Thu Jun  3 15:32:10 2021 + 301378785 ns usr/share/fonts/hack/.uuid
> 
> But for the second backup above, the precision changed to microsecond 
> (displayed "us" above) for usr/share/fonts and usr/share/fonts/hack but 
> is kept as nonaseconds for usr/share/fonts/.hack and usr.
> 
> Reading code on how differential backup behave about dates, 
> (src/libdar/filtre.cpp line 790), a cat_inode object is created reading 
> information from the filesystem, which mtime is compared with the one of 
> the cat_inode taken from the archive of reference. The comparison takes 
> into account the possible date precision difference (datetime::loose_diff).
> If the date is equal inode created from the filesystem just drops
> attributes to its data but keeps the date and its accuracy from the
> filesystem.
> 
> Why microsecnfs for usr/share/fonts  but not for 
> usr/share/fonts/hack/.uuid ? For libdar there is not code difference for 
> directory and other inodes concerning date handling (same cat_inode is 
> the ancestor class that handles all that is common to inodes, in 
> particular dates).
> 
> Same for the third backup below:
> 
> # dar -l MNGR_20240407T000001_san1__zdata_os_services_binhost_root -g
> usr/share/fonts/hack -afdd
> Warning: using insecure memory!
> [Data ][D][ EA  ][FSA][Compr][S]| Permission | User  | Group | Size    |
>           Date                 |    filename
> --------------------------------+------------+-------+-------+---------+----
> ---------------------------+------------
 [     ][-]       [---][     ][ ] 
> drwxr-xr-x   root     root    0 Thu Mar 28 10:57:11 2024 + 379415752 ns usr
> [     ][-]       [---][     ][ ]  drwxr-xr-x   root     root    0
> Thu Mar 28 07:53:02 2024 + 534986022 ns usr/share
> [     ][-]       [---][     ][ ]  drwxr-xr-x   root     root    0
> Thu Jun  3 15:32:10 2021 + 211378 us    usr/share/fonts
> [     ][-]       [---][     ][ ]  drwxr-xr-x   root     root    0
> Thu Jun  3 15:32:10 2021 + 301378 us    usr/share/fonts/hack
> [     ][ ]       [---][-----][ ]  -rw-r--r--   root     root    36 o
> Thu Jun  3 15:32:10 2021 + 301378785 ns usr/share/fonts/hack/.uuid
> 
> Finally for the fourth backup, the precision has even dropped one step 
> further, to second for usr/share, usr/share/fonts and the deleted entry 
> holding place of usr/share/fonts/hack/.uuid which date is read at the 
> time of the backup from the mtime value of the parent directory:
> 
> # dar -l MNGR_20240414T000001_san1__zdata_os_services_binhost_root -g
> usr/share/fonts/hack -afdd
> Warning: using insecure memory!
> [Data ][D][ EA  ][FSA][Compr][S]| Permission | User  | Group | Size    |
>           Date                 |    filename
> --------------------------------+------------+-------+-------+---------+----
> ---------------------------+------------
 [     ][-]       [---][  74%][ ] 
> drwxr-xr-x   root     root    450 Mio Thu Mar 28 10:57:11 2024 + 379415752
> ns usr
> [InRef][-]       [-L-][  91%][ ]  drwxr-xr-x   root     root    233 Mio
> Mon Apr  8 13:19:02 2024 + 244801698 ns usr/share
> [     ][-]       [-L-][     ][ ]  drwxr-xr-x   root     root    0
> Thu Jun  3 15:32:10 2021        usr/share/fonts
> [     ][-]       [-L-][     ][ ]  drwxr-xr-x   root     root    0
> Thu Jun  3 15:32:10 2021        usr/share/fonts/hack
> [--- REMOVED ENTRY ----] (Thu Jun  3 15:32:10 2021) [-]
> usr/share/fonts/hack/.uuid
> 
> I tried reproducing this with backup, differential backup, backup 
> isolation on an filesystem with mounted with relatime option without 
> success... all works as expected on my side.

Yes, and it's strange this only happened to 1 of several VMs/systems.

> > It was recompiled recently (on the 10th), with me noticing the issue on 
> > the 13th or 14th.
> > But the other hosts are backed up using the exact same Dar-version. (Dar 
> > runs on the storage host which contains all the VMs. Some VMs are 
> > practically identical)
> > 
> > A backup is basically (in reality more complex due to automation) done 
> > as follows:
> > - filesystem snapshot is created
> > - snapshot is mounted
> > - snapshot is backed up using dar
> > - snapshot is umounted + removed
> 
> So my question is now about the snapshot process and the way you expose 
> it to dar.

commands run (simplistically, nothing special is actually performed):
# zfs snapshot ....
# mount -oro /dev/zvol/.....  /mnt/darroot
# dar .... /mnt/darroot

> Could you issue the following command for example in such snapshot:
> 
> stat /usr/share/fonts/hack

# stat /usr/share/fonts/hack
  File: /usr/share/fonts/hack
  Size: 4096            Blocks: 8          IO Block: 4096   directory
Device: 202,1   Inode: 532613      Links: 2
Access: (0755/drwxr-xr-x)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2022-08-02 08:56:46.000000000 +0000
Modify: 2021-06-03 13:32:10.000000000 +0000
Change: 2024-04-08 06:13:39.937335727 +0000
 Birth: 2017-10-26 11:41:16.541269703 +0000

[...]

> In conclusion so far, the explanation of the warning issued by 
> dar_manager is caused by a loss of time precision and is not a bug in 
> dar_manager, maybe still possible a bug in dar but that is not the most 
> probable explanation IMHO.

I can't fully check the actual timeline and what happened as not all logs are 
kept this long, which currently is quite annoying. I wish I knew how to 
reproduce this. Going forward, I have increased log-retention and if it occurs 
again, I should have a better idea on how to reproduce this issue.

Looking at the output of the "stat" command, I wonder if "tar", by default, 
only stores second-level precision, leading to the ".000000000 +0000" I see 
for "access" and "modify"

The filesystem has been the same for years and the OS is simply being kept 
uptodate over time.

What does "dar" do when it sees ".000000000 +0000" at the end? Does it reduce 
the precision to match the lowest non-zero field?

If the above doesn't yield anything pointing to a specific issue in dar/
dar_manager, I would suggest we leave this as-is and wait for it to happen 
again.

--
Joost