{"id":16899,"date":"2012-11-29T19:03:16","date_gmt":"2012-11-30T00:03:16","guid":{"rendered":"https:\/\/nuxx.net\/blog\/?p=16899"},"modified":"2012-11-29T23:04:30","modified_gmt":"2012-11-30T04:04:30","slug":"fixing-nuxx-nets-backups","status":"publish","type":"post","link":"https:\/\/nuxx.net\/blog\/2012\/11\/29\/fixing-nuxx-nets-backups\/","title":{"rendered":"Fixing nuxx.net’s Backups"},"content":{"rendered":"

nuxx.net has a backup system which uses rsync<\/a> to back up the server (and everything it hosts) to my desktop iMac, deduplicating the files by way of rsync’s --link-dest<\/tt> argument to create hard links (detailed info here<\/a>). Maintaining a 30 day backup history it only uses the space of one full backup plus 29 days of change, which isn’t much given the utility allowed. It’s been running fine for a few years, but about a month or so ago I began getting errors where the target disk for the backups was full, which seemed a bit odd to me. As a stopgap I was able to clean up some other things and keep backups working, but the space was a lot more than normal.<\/p>\n

Today I managed to get this resolved, but it took a bit of digging. Below the fold you can see what I found.<\/p>\n


\nAfter a bit of initial investigation, this is what I knew:<\/p>\n

· Some files, generally those written before a certain date, were appropriately being deduplicated via hard links and thus had the same inode<\/a>.
\n· Newer files weren’t getting deduplicated and had different inodes.
\n· The lack of deduplication (especially with the large nightly database dumps) was contributing to the volume becoming full.
\n· Looking at the Number of files transferred:<\/tt> entries in each of the daily rsync logs the numbers weren’t increasing, as one would expect if existing files weren’t being found locally, so the backup must have been referencing the files in --link-dest<\/tt>. They generally stayed at 100-300 per day, for the last many months.<\/p><\/blockquote>\n

By setting up two test cases running rsync -vvvv<\/tt> (a very verbose mode) against one file that wasn’t being deduplicated and one that was, I saw these lines in the not-getting-deduplicated log file needed it’s UID and GID changed:<\/p>\n

set uid of IMG_7118.jpg from 99 to 1001<\/tt>
\nset gid of IMG_7118.jpg from 99 to 1001<\/tt><\/p><\/blockquote>\n

In both cases I saw that the file wasn’t being transferred. Both looked similar to this:<\/p>\n

Number of files: 1<\/tt>
\nNumber of files transferred: 0<\/tt>
\nTotal file size: 4779530 bytes<\/tt>
\nTotal transferred file size: 0 bytes<\/tt><\/p><\/blockquote>\n

Checking this file on the target disk showed that it’s UID and GID were not changed as described in the verbose log, so that gave me a place to start.<\/p>\n

I then looked at the disk from the machine itself, and while I could create files, I couldn’t change their ownership:<\/p>\n

quicksilver:darktrain.nuxx.net root# touch blah<\/tt>
\nquicksilver:darktrain.nuxx.net root# ls -alsn blah<\/tt>
\n0 -rw-r--r-- 1 99 99 0 Nov 29 13:17 blah<\/tt>
\nquicksilver:darktrain.nuxx.net root# chown 1001:1001 blah<\/tt>
\nquicksilver:darktrain.nuxx.net root# ls -alsn blah<\/tt>
\n0 -rw-r--r-- 1 99 99 0 Nov 29 13:17 blah<\/tt>
\nquicksilver:darktrain.nuxx.net root#<\/tt><\/p><\/blockquote>\n

Based on this, I figured I’d see what fsck<\/a> had to say:<\/p>\n

quicksilver:~ root# fsck_hfs -f \/dev\/disk3s3<\/tt>
\n** \/dev\/rdisk3s3 (NO WRITE)<\/tt>
\n        Using cacheBlockSize=32K cacheTotalBlock=65536 cacheSize=2097152K.<\/tt>
\n   Executing fsck_hfs (version diskdev_cmds-557~393).<\/tt>
\n** Verifying volume when it is mounted with write access.<\/tt>
\n   Journal need to be replayed but volume is read-only<\/tt>
\n** Checking Journaled HFS Plus volume.<\/tt>
\n** Detected a case-sensitive volume.<\/tt>
\n   The volume name is Cruft<\/tt>
\n** Checking extents overflow file.<\/tt>
\n** Checking catalog file.<\/tt>
\n** Checking multi-linked files.<\/tt>
\n   Incorrect number of file hard links<\/tt>
\n** Checking catalog hierarchy.<\/tt>
\n** Checking extended attributes file.<\/tt>
\n** Checking volume bitmap.<\/tt>
\n** Checking volume information.<\/tt>
\n** The volume Cruft was found corrupt and needs to be repaired.<\/tt>
\nquicksilver:~ root#<\/tt><\/p><\/blockquote>\n

Well, that’s something… Maybe diskutil<\/a>, Apple’s utility for repairing disks, can help out:<\/p>\n

quicksilver:~ root# diskutil repairVolume \/Volumes\/Cruft\/<\/tt>
\nStarted file system repair on disk3s3 Cruft<\/tt>
\nChecking file system<\/tt>
\nChecking Journaled HFS Plus volume<\/tt>
\nDetected a case-sensitive volume<\/tt>
\nChecking extents overflow file<\/tt>
\nChecking catalog file<\/tt>
\nChecking multi-linked files<\/tt>
\nIncorrect number of file hard links<\/tt>
\nChecking catalog hierarchy<\/tt>
\nChecking extended attributes file<\/tt>
\nChecking volume bitmap<\/tt>
\nChecking volume information<\/tt>
\nRepairing volume<\/tt>
\nOrphaned file inode (id = 108285)<\/tt>
\nOrphaned file inode (id = 3609024)<\/tt>
\nLook for missing items in lost+found directory<\/tt>
\nRechecking volume<\/tt>
\nChecking Journaled HFS Plus volume<\/tt>
\nDetected a case-sensitive volume<\/tt>
\nChecking extents overflow file<\/tt>
\nChecking catalog file<\/tt>
\nChecking multi-linked files<\/tt>
\nChecking catalog hierarchy<\/tt>
\nIncorrect folder count in a directory (id = 2)<\/tt>
\n(It should be 13 instead of 12)<\/tt>
\nChecking extended attributes file<\/tt>
\nChecking volume bitmap<\/tt>
\nChecking volume information<\/tt>
\nRepairing volume<\/tt>
\nRechecking volume<\/tt>
\nChecking Journaled HFS Plus volume<\/tt>
\nDetected a case-sensitive volume<\/tt>
\nChecking extents overflow file<\/tt>
\nChecking catalog file<\/tt>
\nChecking multi-linked files<\/tt>
\nChecking catalog hierarchy<\/tt>
\nChecking extended attributes file<\/tt>
\nChecking volume bitmap<\/tt>
\nChecking volume information<\/tt>
\nThe volume Cruft was repaired successfully<\/tt>
\nVolume repair complete<\/tt>
\nUpdating boot support partitions for the volume as required<\/tt>
\nFinished file system repair on disk3s3 Cruft<\/tt>
\nquicksilver:~ root#<\/tt><\/p><\/blockquote>\n

Unfortunately, that didn’t make it better either. After reading up a bit on Apple’s Ignore ownership<\/em> setting for external drives (which I explicitly had to disable when setting this system up and had somewhat forgotten about) I found this setting is stored in \/var\/db\/volinfo.database<\/tt>:<\/p>\n

quicksilver:darktrain.nuxx.net root# cat \/var\/db\/volinfo.database<\/tt>
\nAB8A61B83C455765: 00000001<\/tt>
\nD3572298D5E48D13: 00000001<\/tt>
\n66408CB4FDEFB639: 00000001<\/tt>
\nquicksilver:darktrain.nuxx.net root#<\/tt><\/p><\/blockquote>\n

Hmm, okay. Only three entries… That seems odd. I have more drives than that. Apparently this setting is also be reflected as the noowners<\/tt> option on mount:<\/p>\n

quicksilver:darktrain.nuxx.net root# mount<\/tt>
\n\/dev\/disk0s2 on \/ (hfs, local, journaled)<\/tt>
\ndevfs on \/dev (devfs, local, nobrowse)<\/tt>
\n\/dev\/disk1s2 on \/Volumes\/Thunder (hfs, local, journaled)<\/tt>
\nmap -hosts on \/net (autofs, nosuid, automounted, nobrowse)<\/tt>
\nmap auto_home on \/home (autofs, automounted, nobrowse)<\/tt>
\n\/dev\/disk2s2 on \/Volumes\/WIN7 (ntfs, local, nodev, nosuid, read-only, noowners)<\/tt>
\n\/dev\/disk5s2 on \/Volumes\/Time Machine (hfs, local, nodev, nosuid, journaled)<\/tt>
\n\/dev\/disk3s3 on \/Volumes\/Cruft (hfs, local, nodev, nosuid, journaled, noowners)<\/tt>
\nquicksilver:darktrain.nuxx.net root#<\/tt><\/p><\/blockquote>\n

Ah hah! Now to get rid of noowners on \/Volumes\/Cruft<\/tt>…<\/p>\n

quicksilver:~ root# diskutil enableOwnership \/Volumes\/Cruft\/<\/tt>
\nFile system user\/group ownership enabled<\/tt>
\nquicksilver:~ root#<\/tt><\/p><\/blockquote>\n

Are there now more entries in <\/tt>\/var\/db\/volinfo.database<\/tt>?<\/p>\n

quicksilver:darktrain.nuxx.net root# cat \/var\/db\/volinfo.database<\/tt>
\nAB8A61B83C455765: 00000001<\/tt>
\nD3572298D5E48D13: 00000001<\/tt>
\n66408CB4FDEFB639: 00000001<\/tt>
\nA345AB3A480EFF2A: 00000001<\/tt>
\nquicksilver:darktrain.nuxx.net root#<\/tt><\/p><\/blockquote>\n

Yep! So, did it work?<\/p>\n

quicksilver:darktrain.nuxx.net root# mount<\/tt>
\n\/dev\/disk0s2 on \/ (hfs, local, journaled)<\/tt>
\ndevfs on \/dev (devfs, local, nobrowse)<\/tt>
\n\/dev\/disk1s2 on \/Volumes\/Thunder (hfs, local, journaled)<\/tt>
\nmap -hosts on \/net (autofs, nosuid, automounted, nobrowse)<\/tt>
\nmap auto_home on \/home (autofs, automounted, nobrowse)<\/tt>
\n\/dev\/disk2s2 on \/Volumes\/WIN7 (ntfs, local, nodev, nosuid, read-only, noowners)<\/tt>
\n\/dev\/disk5s2 on \/Volumes\/Time Machine (hfs, local, nodev, nosuid, journaled)<\/tt>
\n\/dev\/disk3s3 on \/Volumes\/Cruft (hfs, local, nodev, nosuid, journaled)<\/tt>
\nquicksilver:darktrain.nuxx.net root#<\/tt><\/p><\/blockquote>\n

Mount looks good…<\/p>\n

quicksilver:darktrain.nuxx.net root# ls -alsn blah<\/tt>
\n0 -rw-r--r-- 1 0 80 0 Nov 29 16:53 blah<\/tt>
\nquicksilver:darktrain.nuxx.net root# chown 1001:1001 blah<\/tt>
\nquicksilver:darktrain.nuxx.net root# ls -alsn blah<\/tt>
\n0 -rw-r--r-- 1 1001 1001 0 Nov 29 16:53 blah<\/tt>
\nquicksilver:darktrain.nuxx.net root#<\/tt><\/p><\/blockquote>\n

Looks like it did! Now to run two backup jobs (one to ensure the data is all there with the right permissions, and the second to reference it) and see if the those two most recent backups (backup.0<\/tt> and backup.1<\/tt>) have the previously-problematic file now sharing the same inode:<\/p>\n

quicksilver:darktrain.nuxx.net root# ls -i backup.*\/c0nsumer\/gallery2_data\/nuxx.net\/albums\/acquired_stuff\/IMG_7118.jpg<\/tt>
\n80384029 backup.0\/c0nsumer\/gallery2_data\/nuxx.net\/albums\/acquired_stuff\/IMG_7118.jpg<\/tt>
\n80384029 backup.1\/c0nsumer\/gallery2_data\/nuxx.net\/albums\/acquired_stuff\/IMG_7118.jpg<\/tt>
\n80144307 backup.2\/c0nsumer\/gallery2_data\/nuxx.net\/albums\/acquired_stuff\/IMG_7118.jpg<\/tt>
\n79905924 backup.3\/c0nsumer\/gallery2_data\/nuxx.net\/albums\/acquired_stuff\/IMG_7118.jpg<\/tt>
\n[...snip...]<\/tt>
\nquicksilver:darktrain.nuxx.net root#<\/tt><\/p><\/blockquote>\n

They do! So, that’s what the problem was… Because the ownership of the files on the destination (the iMac) couldn’t be changed, rsync apparently created a copy instead of a hard link. Thus the increase in space. But, apparently because the checksum of the files matched it was never re-transferred, which is why there was not a consistently increasing Number of files transfered<\/tt> in the rsync log.<\/p>\n

That brings about the next question: how did this happen? I suspect that when I replaced my failed SSD in the iMac (where the OS resides) \/var\/db\/volinfo.database<\/tt> didn’t get restored by Time Machine. Or, maybe it did and the external drive was given a new identifier? I’m not sure what the entries in volinfo.database<\/tt> refer to, as they aren’t the volume GUIDs, so I can’t really check that.<\/p>\n

Still, I’m glad this problem is sorted out and I know why it wasn’t working. I’ll now just wait 30 days for the old, only-partially-deduplicated backups to rotate out and everything will be good again.<\/p>\n","protected":false},"excerpt":{"rendered":"

nuxx.net has a backup system which uses rsync to back up the server (and everything it hosts) to my desktop iMac, deduplicating the files by<\/p>\n

Continue readingFixing nuxx.net’s Backups<\/span><\/a><\/div>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[13],"tags":[],"class_list":["post-16899","post","type-post","status-publish","format-standard","hentry","category-computers","entry"],"amp_enabled":true,"_links":{"self":[{"href":"https:\/\/nuxx.net\/blog\/wp-json\/wp\/v2\/posts\/16899","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/nuxx.net\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/nuxx.net\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/nuxx.net\/blog\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"https:\/\/nuxx.net\/blog\/wp-json\/wp\/v2\/comments?post=16899"}],"version-history":[{"count":43,"href":"https:\/\/nuxx.net\/blog\/wp-json\/wp\/v2\/posts\/16899\/revisions"}],"predecessor-version":[{"id":16942,"href":"https:\/\/nuxx.net\/blog\/wp-json\/wp\/v2\/posts\/16899\/revisions\/16942"}],"wp:attachment":[{"href":"https:\/\/nuxx.net\/blog\/wp-json\/wp\/v2\/media?parent=16899"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/nuxx.net\/blog\/wp-json\/wp\/v2\/categories?post=16899"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/nuxx.net\/blog\/wp-json\/wp\/v2\/tags?post=16899"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}