Bug 1410238 - logrotate creates unwanted 0-length files
Summary: logrotate creates unwanted 0-length files
Alias: None
Product: Fedora EPEL
Classification: Fedora
Component: mongodb
Version: epel7
Hardware: Unspecified
OS: Unspecified
Target Milestone: ---
Assignee: Marek Skalický
QA Contact: Fedora Extras Quality Assurance
Depends On:
TreeView+ depends on / blocked
Reported: 2017-01-04 21:14 UTC by Michael Hrivnak
Modified: 2017-01-29 03:18 UTC (History)
10 users (show)

Fixed In Version: mongodb-2.6.12-4.el7
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Last Closed: 2017-01-29 03:18:37 UTC
Type: Bug

Attachments (Terms of Use)

Description Michael Hrivnak 2017-01-04 21:14:24 UTC
Description of problem:
When using the provided logrotate config, extra files are created. For example, I have a directory listing of /var/log/mongodb/ like this:

-rw-r--r--. 1 mongodb mongodb  13K Jan  4 15:34 mongodb.log
-rw-r--r--. 1 mongodb mongodb 2.6M Nov 20 03:40 mongodb.log-20161120.gz
-rw-r--r--. 1 mongodb mongodb    0 Nov 20 03:40 mongodb.log.2016-11-20T08-40-04
-rw-r--r--. 1 mongodb mongodb  27K Nov 28 03:50 mongodb.log-20161128.gz
-rw-r--r--. 1 mongodb mongodb    0 Nov 28 03:50 mongodb.log.2016-11-28T08-50-03
-rw-r--r--. 1 mongodb mongodb 8.0K Dec  4 03:43 mongodb.log-20161204.gz
-rw-r--r--. 1 mongodb mongodb    0 Dec  4 03:43 mongodb.log.2016-12-04T08-43-02
-rw-r--r--. 1 mongodb mongodb 6.7K Dec 12 03:49 mongodb.log-20161212.gz
-rw-r--r--. 1 mongodb mongodb    0 Dec 12 03:49 mongodb.log.2016-12-12T08-49-02
-rw-r--r--. 1 mongodb mongodb 1.1M Dec 18 03:16 mongodb.log-20161218.gz
-rw-r--r--. 1 mongodb mongodb    0 Dec 18 03:16 mongodb.log.2016-12-18T08-16-02
-rw-r--r--. 1 mongodb mongodb  99K Dec 25 03:36 mongodb.log-20161225.gz
-rw-r--r--. 1 mongodb mongodb    0 Dec 25 03:36 mongodb.log.2016-12-25T08-36-02
-rw-r--r--. 1 mongodb mongodb 5.9K Jan  2 03:42 mongodb.log-20170102
-rw-r--r--. 1 mongodb mongodb    0 Jan  2 03:42 mongodb.log.2017-01-02T08-42-02

Each of the 0-length files should not be present.

The included logrotate config looks like this:

$ cat /etc/logrotate.d/mongodb 
/var/log/mongodb/*.log {
       rotate 10
          /bin/kill -USR1 `cat /var/run/mongodb/mongod.pid 2>/dev/null` 2> /dev/null|| true

This is what I think is happening, using data above as an example:

- logrotate operated as normal. It renamed mongodb.log to mongodb.log-20170102, and then created a new 0-length mongodb.log
- the "postrotate" command ran, which sent SIGUSR1 to the mongodb process. Per mongo's documentation [0], that caused mongodb to invoke *its own implementation of log rotation*
- mongodb thus renamed the brand-new-and-empty mongodb.log file to mongodb.log.2017-01-02T08-42-02, and created a new mongodb.log file.

So in effect, log rotation is happening twice in rapid succession. Only one of them needs to actually happen.

[0] https://docs.mongodb.com/v2.6/tutorial/rotate-log-files/#overview

Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1. start mongodb
2. run logrotate

Actual results:
an extra 0-length file in /var/log/mongodb/

Expected results:
just the rotated log files plus a current/active log file

Comment 1 Peter Vreman 2017-01-05 07:33:00 UTC
Additoinal to the 0-length files also spare files that look huge can be created.
After logrotate moves the file, then mongod is still writing to the file at postiion <huge> and then creates a sparse file. Quickly after that the USR1 is received by mongod and also mongod is switching.

See the Size vs. Blocks in the stat and the hexdump of the first 20 0x00 characters:

[crash] root@li-lc-1017:~# head -c 20 /var/log/mongodb/mongodb.log.2016-12-05T03-22-28 | xxd
0000000: 0000 0000 0000 0000 0000 0000 0000 0000  ................
0000010: 0000 0000                                ....

[crash] root@li-lc-1017:~# stat /var/log/mongodb/mongodb.log.2016-12-05T03-22-28
  File: ‘/var/log/mongodb/mongodb.log.2016-12-05T03-22-28’
  Size: 1342099293      Blocks: 16         IO Block: 4096   regular file
Device: fd07h/64775d    Inode: 11156       Links: 1
Access: (0644/-rw-r--r--)  Uid: (  184/ mongodb)   Gid: (  130/ mongodb)
Context: system_u:object_r:mongod_log_t:s0
Access: 2017-01-04 16:14:49.667227212 +0000
Modify: 2016-12-05 03:22:28.217426986 +0000
Change: 2016-12-05 03:22:28.388427487 +0000
 Birth: -

Comment 2 Marek Skalický 2017-01-09 10:31:26 UTC
Upstream introduced fix for this in MongoDB 3.0 - https://docs.mongodb.com/v3.0/tutorial/rotate-log-files/#log-rotation-with-logrotate-reopen (this option improve working with logrotate utility and solves this problem).

For MongoDB 2.6 EPEL7 workaround is needed. I am preparing fix which will: copy config file, do MongoDB logrotation (result empty/big file + starting using new file) and remove files from MongoDB logrotation.

Comment 3 Fedora Update System 2017-01-12 10:43:14 UTC
mongodb-2.6.12-4.el7 has been submitted as an update to Fedora EPEL 7. https://bodhi.fedoraproject.org/updates/FEDORA-EPEL-2017-5805758e8b

Comment 4 Fedora Update System 2017-01-13 07:48:01 UTC
mongodb-2.6.12-4.el7 has been pushed to the Fedora EPEL 7 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-EPEL-2017-5805758e8b

Comment 5 Michael Hrivnak 2017-01-13 19:47:41 UTC
Thanks for the quick resolution!

Comment 6 Fedora Update System 2017-01-29 03:18:37 UTC
mongodb-2.6.12-4.el7 has been pushed to the Fedora EPEL 7 stable repository. If problems still persist, please make note of it in this bug report.

Note You need to log in before you can comment on or make changes to this bug.