id,summary,reporter,owner,description,type,status,milestone,component,version,severity,resolution,keywords,cc
11016,Boost file logging misbehaves when file system is full,michi@…,Andrey Semashev,"I'm using boost log with log files. Code is simple and works fine:


{{{
FileSinkPtr s = boost::make_shared<FileSinkT>(
                        keywords::file_name = path + ""-%N.log"",
                        keywords::rotation_size = rotation_size);
string parent = boost::filesystem::path(path).parent_path().native();
    s->locked_backend()->set_file_collector(sinks::file::make_collector(keywords::target = parent,
                                                                        keywords::max_size = dir_size));
s->locked_backend()->scan_for_files();

}}}

Rotation size is set to max 512 kB, and log dir size to max 10 MB.

All this works fine. When I run a test that does some logging, I see the log files created and rotated as they should be.

In an unrelated test of our code, I decided to test the robustness of file-related operations, to see whether our code would hold up when the file system was full. So, I created a small ramdisk that I can fill up to see what happens.

It turns out that, once the file system is full, boost log does bad things. Here are the contents of the log dir after a single run of my test:


{{{
$ ls -l
total 680
-rw-rw-r-- 1 michi michi 524172 Feb 12 11:38 PusherScope-0.log
-rw-rw-r-- 1 michi michi 170249 Feb 12 11:38 PusherScope-1.log
}}}


This is in a 10 MB file system:


{{{
$ df
Filesystem      1K-blocks      Used  Available Use% Mounted on
tmpfs               10240      3480       6760  34% /home/michi/tmp/ramdisk
}}}


The test runs several processes, some of which also log into the same file system (but each process logs into a different directory).

Running the test a second time, I see:

{{{

$ ls -l
total 1360
-rw-rw-r-- 1 michi michi 524172 Feb 12 11:38 PusherScope-0.log
-rw-rw-r-- 1 michi michi 170249 Feb 12 11:38 PusherScope-1.log
-rw-rw-r-- 1 michi michi 524252 Feb 12 11:40 PusherScope-2.log
-rw-rw-r-- 1 michi michi 170169 Feb 12 11:40 PusherScope-3.log
}}}


Things are still fine, just as I would expect.


{{{
$ df
Filesystem      1K-blocks      Used  Available Use% Mounted on
tmpfs               10240      6960       3280  68% /home/michi/tmp/ramdisk
}}}

Running the test a third time causes the file system to fill up:


{{{
$ df
Filesystem      1K-blocks      Used  Available Use% Mounted on
tmpfs               10240     10240          0 100% /home/michi/tmp/ramdisk
}}}


Now, when I look at the log directory, I find five non-empty log files in there:


{{{
$ ls -l
-rw-rw-r-- 1 michi michi 170249 Feb 12 11:38 PusherScope-1.log
-rw-rw-r-- 1 michi michi 524252 Feb 12 11:40 PusherScope-2.log
-rw-rw-r-- 1 michi michi 170169 Feb 12 11:40 PusherScope-3.log
-rw-rw-r-- 1 michi michi 524261 Feb 12 11:42 PusherScope-4.log
-rw-rw-r-- 1 michi michi 135168 Feb 12 11:42 PusherScope-5.log
...
}}}


In addition, there are now 280 (!) empty log files there. Small excerpt:


{{{
total 2004
-rw-rw-r-- 1 michi michi 524172 Feb 12 11:38 PusherScope-0.log
-rw-rw-r-- 1 michi michi      0 Feb 12 11:42 PusherScope-100.log
-rw-rw-r-- 1 michi michi      0 Feb 12 11:42 PusherScope-101.log
-rw-rw-r-- 1 michi michi      0 Feb 12 11:42 PusherScope-102.log
-rw-rw-r-- 1 michi michi      0 Feb 12 11:42 PusherScope-103.log
-rw-rw-r-- 1 michi michi      0 Feb 12 11:42 PusherScope-104.log
etc, etc...
}}}


It's the same story for other log directories in the file system, where other processes also log and do the exact same thing.

If I continue to run the test in a loop, this continues, adding more and more empty log files. Eventually, the file system runs out of inodes:


{{{
$ df -i
Filesystem        Inodes    IUsed     IFree IUse% Mounted on
tmpfs            2040639  1213366    827273   60% /home/michi/tmp/ramdisk
}}}


(I stopped the test at that point, by which I had more than a million empty files.)",Bugs,closed,To Be Determined,log,Boost 1.55.0,Problem,fixed,,