[SERVER-14053] implementation of server logRotate command breaks O_APPEND semantics which breaks the logrotate utility's copytruncate Created: 26/May/14  Updated: 10/Jul/14  Resolved: 10/Jul/14

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Akshay Kumar Assignee: Unassigned
Resolution: Won't Fix Votes: 2
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
related to SERVER-4905 logRotate should conform to standard ... Closed
Operating System: ALL
Participants:

 Description   

I am seeing a totally bizarre interaction with mongod and logrotate's copytruncate which I could only reproduce occasionally where the truncated file would be sparse and full of NULL bytes till the point it got rotated. It would only happen on some boxes. After some digging it turns out that running logRotate at any point in time breaks O_APPEND and all writes keep going to the last_offset that was written to instead.

  • logrotate is configured to rotate mongod.log when it hits 1G
  • logrotate runs through a cron job every 15 min
  • since SIGUSR1 doesn't reopen the file I make logrotate do copytruncate instead. That just moves mongod.log to mongod.log1. logrotate does something like:

while ((cnt = read(fdcurr, buf, sizeof(buf))) > 0)
    write(fdsave, buf, cnt)
 
ftruncate(currLog, 0)

  • Now since I have the logappend option to mongod enabled I'd expect it to do O_APPEND on open. Which it does:

open("/home2/akshay/logtest/mongod.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 4

All good so far. Now I'd expect the rotated log file to be size 0. Since we opened with O_APPEND the file_offset in the file table entry will be reset to 0 on the next write since that's the new size in the i-node table entry.

Instead what I get is a sparse file with all null bytes at the beginning. So if logrotate happened to run at 1.2G I have a sparse mongod.log that is 1.2G. Doesn't take up any extra space yet cause ext4 supports sparse files which is all fine till the next iteration.

Now when logrotate comes around this time and starts copying, the new rotated file (mongod.log.x) is exploded, it's not longer sparse. The original logfile (mongod.log) is now 2.x G and sparse and the cycle continues with each subsequent rotated file (mongod.log.x) getting bigger and bigger until it runs out of diskspace.

The only way for this to happen is if something keeps writing to the last_offset thereby bypassing the O_APPEND semantics. Turns out it was only happening on boxes where I had previously run the server's logRotate command:

db.runCommand({logRotate:1})

To reproduce:

  • start a mongod with --logappend
  • let it log for a bit, at least over 4k or so, you can increase verbosity
  • run ftruncate mongod.log and do head -n 2 mongod.log, everything should be fine and you should see the first couple of lines
  • let mongod log for a bit, do db.runCommand( {logRotate:1}

    ) and again let it log for a bit

  • do ftruncate mongod.log another time

You should now see a sparse file, ls -lhs should show you the size on disk vs the actual size. Now do od -c mongod.log and you should see something like the following.

All bytes till 0160220 are NULL.

[akshay@maverick logtest]$ od -c mongod.log
0000000  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0
*
0160220   2   0   1   4   -   0   5   -   2   5   T   1   2   :   1   8
0160240   :   5   9   .   5   6   9   -   0   4   0   0       [   j   o
0160260   u   r   n   a   l   ]       _   g   r   o   u   p   C   o   m



 Comments   
Comment by Mark Benvenuto [ 10/Jul/14 ]

We have implemented better log rotation behavior to conform with the logrotate's expectations. See SERVER-4905 for more information.

Comment by Akshay Kumar [ 26/May/14 ]

That would definitely be the best way to go about it. With copytruncate you lose some logs between the copy and truncate operations so it's not ideal and it would only work if you never ran the server logRotate command after starting mongod.

Right now the best workaround if you want to do logrotate is the following:

/var/log/mongodb/mongod.log {
  daily
  size 1G
  rotate 10
  missingok
  compress
  delaycompress
  notifempty
  create 640 mongod mongod
  sharedscripts
  postrotate
      /bin/kill -SIGUSR1 `cat /var/run/mongodb/mongod.pid 2>/dev/null` >/dev/null 2>&1
      find /var/log/mongodb -type f -size 0 -regextype posix-awk -regex "^\/var\/log\/mongodb\/mongod\.log\.[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}-[0-9]{2}-[0-9]{2}$" -execdir rm {} \; >/dev/null 2>&1
  endscript
}

Comment by Andy Schwerin [ 26/May/14 ]

akshay, would implementing SERVER-4905, and perhaps back porting it to 2.6, suffice for your purposes?

Generated at Thu Feb 08 03:33:42 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.