Cleanup not working

Ive been using urbackup 1.3.2 for over a year now and I love it.

I noticed the backup server’s drive becoming very full.

Filesystem               Size    Used   Avail Capacity  Mounted on
backup/urbackup           12T     12T    432G    97%       /backup/urbackup

In the urbackup statistics it says its using about 43TB total.

Images	1.38 TB
Files	42.36 TB
All	43.74 TB

From what I have been able to guess urbackup does cleanup based on the global soft quota (30T) and its own statistics (44T) and not the actually filesystem space used (12T).

Global soft filesystem quota: 30T

My cleanup time is,

Cleanup time window: 1-7/3-12

And I do see some deletes in the ‘Activities’ on a daily basis, but its never enough to get below the soft quota and my storage space is going to fill up completely soon.

I attempted to run urbackup with “–app clean --cleanup_amount 3T” and it would just zip right through the cleanup processing saying it would remove 3T but it never does anything and exits almost immediately.

I thought maybe there is a bug in 1.3.2 so I upgraded the box to the latest 1.4.10. I then issued the same manual cleanup command and this time it actually did delete some backups and clear a little bit of space.

2015-11-16 09:37:02: Cleaning up 3 TB on backup storage
2015-11-16 09:37:02: Database cache size is 400 MB
2015-11-16 09:37:02: Starting cleanup...
2015-11-16 09:37:02: Freeing database connections...
2015-11-16 09:37:02: Deleting client with id "5" name "sql"
2015-11-16 09:37:02: Removing image with id "3638"
2015-11-16 09:37:12: Removing image with id "4259"
...
2015-11-16 10:18:29: Updating del files stats: 99%
2015-11-16 10:18:29: File processing speed: 307.692 files/s
2015-11-16 10:18:29: Updating del files stats: 100%
2015-11-16 10:18:29: Updating file stats...
2015-11-16 10:18:29: Done updating statistics.
2015-11-16 10:18:29: Cleanup successfull.

After it was finished it had freed up 1% of the actual filesystem to 96% full.

That test gave me hope and I tried to run the exact same command again but this time with 5T to cleanup, and now it does not delete anything again. It just races through the process and exits. I cant get it to clean up space.

cd /usr/local/var

/usr/local/sbin/urbackup_srv
–plugin /usr/local/lib/liburbackupserver_urlplugin.so
–plugin /usr/local/lib/liburbackupserver_cryptoplugin.so
–plugin /usr/local/lib/liburbackupserver_downloadplugin.so
–plugin /usr/local/lib/liburbackupserver_fsimageplugin.so
–plugin /usr/local/lib/liburbackupserver_httpserver.so
–plugin /usr/local/lib/liburbackupserver.so
–http_root /usr/local/var/urbackup/www
–workingdir /usr/local/var
–user urbackup
–http_port 55414
–logfile /var/log/urbackup_srv.log
–no_daemon
–app cleanup
–cleanup_amount 3T
-v
-v
-v

2015-11-16 10:35:29: done.
2015-11-16 10:35:29: Loaded -url- plugin
2015-11-16 10:35:29: Loaded -cryptoplugin- plugin
2015-11-16 10:35:29: Loaded -download- plugin
2015-11-16 10:35:29: Loaded -fsimageplugin- plugin
2015-11-16 10:35:29: Starting HTTP-Server on port 55414
2015-11-16 10:35:29: HTTP: Server started up sucessfully!
2015-11-16 10:35:29: Shutting down all database instances...
2015-11-16 10:35:29: Opening urbackup server database...
Backupfolder not set
2015-11-16 10:35:29: Backup destination cannot handle subvolumes and snapshots. Snapshots disabled.
2015-11-16 10:35:29: Transitioning urbackup server database to different journaling mode...
2015-11-16 10:35:29: Cleaning up 5 TB on backup storage
2015-11-16 10:35:29: Database cache size is 400 MB
2015-11-16 10:35:29: Starting cleanup...
2015-11-16 10:35:29: Freeing database connections...
2015-11-16 10:35:29: Space to free: 5 TB
2015-11-16 10:35:29: Deleting old logs...
2015-11-16 10:35:29: Done deleting old logs
2015-11-16 10:35:29: Cleaning history...
2015-11-16 10:35:29: Rewriting daily history...
2015-11-16 10:35:29: Rewriting monthly history...
2015-11-16 10:35:29: Rewriting yearly history...
2015-11-16 10:35:29: Done cleaning history
2015-11-16 10:35:29: Updating statistics...
2015-11-16 10:35:29: Updating image stats...
2015-11-16 10:35:29: Updating deleted files...
2015-11-16 10:35:29: Updating file stats...
2015-11-16 10:35:29: Done updating statistics.
2015-11-16 10:35:29: Cleanup successfull.

I believe I am asking it to free up 5TB of space, and not free space until you are currently using only 5TB. But either way it isn’t deleting.

The server is FreeBSD 9.3 and the storage is on ZFS with lz4 compression enabled with UrBackup 1.4.10 server.

backup/urbackup refcompressratio 1.52x -
backup/urbackup written 12.1T -
backup/urbackup logicalused 18.4T -
backup/urbackup logicalreferenced 18.4T -

Could you run the manual cleanup again with debug log level? That should output the number of backups it is allowed to delete as per settings.

I looked at the code and it currently neither errors in the manual cleanup or the nightly cleanup if it is not allowed to delete backups and the used storage is greater than the global soft filesystem quota. That is definitely something that needs changing.

Added “–loglevel debug”

2015-11-16 12:01:33: Changing user...
2015-11-16 12:01:33: done.
2015-11-16 12:01:33: Loaded -url- plugin
2015-11-16 12:01:33: Loaded -cryptoplugin- plugin
2015-11-16 12:01:33: Loaded -download- plugin
2015-11-16 12:01:33: Loaded -fsimageplugin- plugin
2015-11-16 12:01:33: Starting HTTP-Server on port 55414
2015-11-16 12:01:33: HTTP: Server started up sucessfully!
2015-11-16 12:01:33: Shutting down all database instances...
2015-11-16 12:01:33: Destroying all databases...
2015-11-16 12:01:33: Opening urbackup server database...
2015-11-16 12:01:33: Created new database connection for urbackup/backup_server.db
2015-11-16 12:01:33: Created new database connection for urbackup/backup_server.db
2015-11-16 12:01:33: Testing if backup destination can handle subvolumes and snapshots...
2015-11-16 12:01:33: Backup destination cannot handle subvolumes and snapshots. Snapshots disabled.
2015-11-16 12:01:33: Transitioning urbackup server database to different journaling mode...
2015-11-16 12:01:33: Cleaning up 5 TB on backup storage
2015-11-16 12:01:33: Database cache size is 400 MB
2015-11-16 12:01:33: Starting cleanup...
2015-11-16 12:01:33: Freeing database connections...
2015-11-16 12:01:33: Destroying all databases...
2015-11-16 12:01:33: Created new database connection for urbackup/backup_server.db
2015-11-16 12:01:33: Space to free: 5 TB
2015-11-16 12:01:33: Enough free space now.
2015-11-16 12:01:33: Enough free space now.
2015-11-16 12:01:33: Deleting old logs...
2015-11-16 12:01:33: Done deleting old logs
2015-11-16 12:01:33: Cleaning history...
2015-11-16 12:01:33: Rewriting daily history...
2015-11-16 12:01:33: Reading history...
2015-11-16 12:01:33: 660 history items read
2015-11-16 12:01:33: Deleting history...
2015-11-16 12:01:33: Writing history...
2015-11-16 12:01:33: Rewriting monthly history...
2015-11-16 12:01:33: Reading history...
2015-11-16 12:01:33: 189 history items read
2015-11-16 12:01:33: Deleting history...
2015-11-16 12:01:33: Writing history...
2015-11-16 12:01:33: Rewriting yearly history...
2015-11-16 12:01:33: Reading history...
2015-11-16 12:01:33: 0 history items read
2015-11-16 12:01:33: Deleting history...
2015-11-16 12:01:33: Writing history...
2015-11-16 12:01:33: Done cleaning history
2015-11-16 12:01:33: Updating statistics...
2015-11-16 12:01:33: Copying files from files_new table...
2015-11-16 12:01:33: Deleting contents of files_new table...
2015-11-16 12:01:33: Updating image stats...
2015-11-16 12:01:33: Updating deleted files...
2015-11-16 12:01:33: Updating file stats...
2015-11-16 12:01:33: Done updating statistics.
2015-11-16 12:01:33: Enough free space now.
2015-11-16 12:01:33: Cleanup successfull.

“Enough free space now” is confusing. Shouldnt it be deleting 5TB of data it has stored, not trying to get to a 5TB level of some kind? It still has 43TB in its stats and 12TB on filesystem.

It is only looking at the operating system reported space usage for this, not its internal. The Enough free space now. is there because the https://www.freebsd.org/cgi/man.cgi?query=statvfs call says there is more than 5T free space on the volume. I’ll have a look at how df is implemented on FreeBSD. In the current code free space in bytes = buf.f_bsize*buf.f_bavail.

The statvfs() and fstatvfs() functions fill the structure pointed to by
buf with garbage.This garbage will occasionally bear resemblance to
file system statistics, but portable applications must not depend on
this.

Quite funny. Let’s rely on this :smile:

I think it is an integer overflow. Can you retry with this patch: Prevent integer overflow on FreeBSD · uroni/urbackup_backend@bd96dd7 · GitHub

1 Like

I worked with a friend of mine and he thinks he has your fix.

test code:

#include 
#include   // for memset
#include 
int main(int argc, char* argv[])
{
    int i;
    int err;
    struct statvfs buf;
    for (i=1; i < argc; i++) {
        memset(&buf, 0, sizeof(buf));
        err = statvfs(argv[i], &buf);
        if (err != 0) {
            perror(argv[i]);
        } else {
            printf("buf.f_bsize     %lu\n", buf.f_bsize);
            printf("buf.f_frsize    %lu\n", buf.f_frsize);
            printf("buf.f_bavail    %lu\n", buf.f_bavail);
            printf("buf.f_bfree     %lu\n", buf.f_bfree);
            printf("f_bsize bytes   %lu\n", buf.f_bsize*buf.f_bavail);
            printf("f_frsize bytes  %lu\n", buf.f_frsize*buf.f_bavail);
        }
    }
}

output:

./a.out /backup/urbackup/
buf.f_bsize     131072
buf.f_frsize    512
buf.f_bavail    984019017
buf.f_bfree     984019017
f_bsize bytes   128977340596224
f_frsize bytes  503817736704

f_frsize * f_bavail = 469.216831684113 GB

ZFS list:

backup/urbackup        12.1T   469G  12.1T  /backup/urbackup

This matches what ZFS says too.

I also tried this on linux, this particular box is BTRFS.

./a.out /
buf.f_bsize     4096
buf.f_frsize    4096
buf.f_bavail    18402033
buf.f_bfree     18879917
f_bsize bytes   75374727168
f_frsize bytes  75374727168

This matches linux df

df -h /
Filesystem      Size  Used Avail Use% Mounted on
/dev/sda1       205G  132G   71G  66% /

Trying this change in urbackup

2015-11-16 13:36:54: Space to free: 2 TB
2015-11-16 13:36:54: Free space: 469.217 GB
2015-11-16 13:36:54: Client with id=4 has 2 full image backups max=2
2015-11-16 13:36:54: Client with id=4 has 4 incremental image backups max=4
...
2015-11-16 13:36:54: Deleting full file backup ( id=6010, backuptime=2015-10-13 06:20:35, path=151013-0007 ) from client "SQL" ( id=6 ) ...
--- os_functions_lin.cpp.orig	2015-08-25 18:00:02.000000000 -0500
+++ os_functions_lin.cpp	2015-11-16 13:32:18.000000000 -0600
@@ -297,7 +297,7 @@
 	struct statvfs64 buf;
 	int rc=statvfs64(Server->ConvertToUTF8(path).c_str(), &buf);
 	if(rc==0)
-		return buf.f_bsize*buf.f_bavail;
+		return buf.f_frsize*buf.f_bavail;
 	else
 		return -1;
 }

Thanks for your quick replies and help uroni!

Last question. What do I set for my soft quota? Based on actual filesystem? Its currently using 12T of space. Do I set it to 10T to keep it within 10T of actual space?

Thanks!

Yes base it on the actual file system, so 10T.

I was looking at the BSD df source code ( https://github.com/freebsd/freebsd/blob/master/bin/df/df.c ), that uses f_bsize as blocksize. But that uses the non-POSIX statfs instead of statvfs. For statvfs on FreeBSD the statfs f_bsize gets mapped to f_frsize (and f_iosize to f_bsize). Very confusing.