[Boost-bugs] [Boost C++ Libraries] #11016: Boost file logging misbehaves when file system is full

Subject: [Boost-bugs] [Boost C++ Libraries] #11016: Boost file logging misbehaves when file system is full
From: Boost C++ Libraries (noreply_at_[hidden])
Date: 2015-02-12 01:59:57

#11016: Boost file logging misbehaves when file system is full
------------------------------+---------------------
 Reporter:  michi@…           |      Owner:  andysem
     Type:  Bugs              |     Status:  new
Milestone:  To Be Determined  |  Component:  log
  Version:  Boost 1.57.0      |   Severity:  Problem
 Keywords:                    |
------------------------------+---------------------
 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.)

-- 
Ticket URL: <https://svn.boost.org/trac/boost/ticket/11016>
Boost C++ Libraries <http://www.boost.org/>
Boost provides free peer-reviewed portable C++ source libraries.