[SERVER-53356] Server log is written at pre-truncated position post truncation Created: 14/Dec/20  Updated: 27/Oct/23  Resolved: 15/Dec/20

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 4.2.10, 4.4.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Oleg Pudeyev (Inactive) Assignee: Unassigned
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: Linux
Steps To Reproduce:

Start RS node
Issue `: > path-to-mongod.log`
Wait 5 seconds

Participants:

 Description   

When I truncate the log using

: > path-to.log

pattern, the server appears to keep writing the log at the same position where the file was pre-truncation.

Example shell session:

serene% ls -l `find /mnt/zram/mongodb/4.4-scm -name \*.log`
-rw-rw-rw- 1 m m 462548363 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/configRepl/rs1/mongod.log
-rw-rw-rw- 1 m m  38755955 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/mongos/mongos_14440.log
-rw-rw-rw- 1 m m  38488489 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/mongos/mongos_14441.log
-rw-rw-rw- 1 m m  57344569 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/shard01/rs1/mongod.log
-rw-rw-rw- 1 m m   3191208 Dec 14 15:46 /mnt/zram/mongodb/4.4-scm/shard01/rs2/mongod.log
-rw-rw-rw- 1 m m  56094408 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/shard02/rs1/mongod.log
-rw-rw-rw- 1 m m   3561329 Dec 14 15:51 /mnt/zram/mongodb/4.4-scm/shard02/rs2/mongod.log
serene% :>/mnt/zram/mongodb/4.4-scm/shard01/rs1/mongod.log 
serene% ls -l `find /mnt/zram/mongodb/4.4-scm -name \*.log`
-rw-rw-rw- 1 m m 462549651 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/configRepl/rs1/mongod.log
-rw-rw-rw- 1 m m  38756124 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/mongos/mongos_14440.log
-rw-rw-rw- 1 m m  38488658 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/mongos/mongos_14441.log
-rw-rw-rw- 1 m m         0 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/shard01/rs1/mongod.log
-rw-rw-rw- 1 m m   3191208 Dec 14 15:46 /mnt/zram/mongodb/4.4-scm/shard01/rs2/mongod.log
-rw-rw-rw- 1 m m  56094408 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/shard02/rs1/mongod.log
-rw-rw-rw- 1 m m   3561329 Dec 14 15:51 /mnt/zram/mongodb/4.4-scm/shard02/rs2/mongod.log
serene% ls -l `find /mnt/zram/mongodb/4.4-scm -name \*.log`
-rw-rw-rw- 1 m m 462549892 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/configRepl/rs1/mongod.log
-rw-rw-rw- 1 m m  38756124 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/mongos/mongos_14440.log
-rw-rw-rw- 1 m m  38488658 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/mongos/mongos_14441.log
-rw-rw-rw- 1 m m         0 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/shard01/rs1/mongod.log
-rw-rw-rw- 1 m m   3191208 Dec 14 15:46 /mnt/zram/mongodb/4.4-scm/shard01/rs2/mongod.log
-rw-rw-rw- 1 m m  56094408 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/shard02/rs1/mongod.log
-rw-rw-rw- 1 m m   3561329 Dec 14 15:51 /mnt/zram/mongodb/4.4-scm/shard02/rs2/mongod.log
serene% ls -l `find /mnt/zram/mongodb/4.4-scm -name \*.log`
-rw-rw-rw- 1 m m 462550133 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/configRepl/rs1/mongod.log
-rw-rw-rw- 1 m m  38756124 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/mongos/mongos_14440.log
-rw-rw-rw- 1 m m  38488658 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/mongos/mongos_14441.log
-rw-rw-rw- 1 m m         0 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/shard01/rs1/mongod.log
-rw-rw-rw- 1 m m   3191208 Dec 14 15:46 /mnt/zram/mongodb/4.4-scm/shard01/rs2/mongod.log
-rw-rw-rw- 1 m m  56094408 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/shard02/rs1/mongod.log
-rw-rw-rw- 1 m m   3561329 Dec 14 15:51 /mnt/zram/mongodb/4.4-scm/shard02/rs2/mongod.log
serene% ls -l `find /mnt/zram/mongodb/4.4-scm -name \*.log`
-rw-rw-rw- 1 m m 462550374 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/configRepl/rs1/mongod.log
-rw-rw-rw- 1 m m  38756124 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/mongos/mongos_14440.log
-rw-rw-rw- 1 m m  38488658 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/mongos/mongos_14441.log
-rw-rw-rw- 1 m m  57344811 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/shard01/rs1/mongod.log
-rw-rw-rw- 1 m m   3191208 Dec 14 15:46 /mnt/zram/mongodb/4.4-scm/shard01/rs2/mongod.log
-rw-rw-rw- 1 m m  56094650 Dec 14 15:53 /mnt/zram/mongodb/4.4-scm/shard02/rs1/mongod.log
-rw-rw-rw- 1 m m   3561329 Dec 14 15:51 /mnt/zram/mongodb/4.4-scm/shard02/rs2/mongod.log

You can see how the size of shard01 rs1 log jumped from 0 to 50 megs.

Since the file was earlier truncated, it now has (in the above example) 50 megs of null bytes followed by the log data.

I expected the server to write the log at the current position so that after truncation I just have the post-truncation data starting from the beginning of the file.

I tested 4.2.10 also with same results and the truncate(1) command with also same results.



 Comments   
Comment by Bruce Lucas (Inactive) [ 15/Dec/20 ]

I should also mention that if the goal is to limit the size of the log file by removing old entries, you should be able to accomplish that using one of the log rotation mechanisms.

Comment by Bruce Lucas (Inactive) [ 15/Dec/20 ]

What you're describing is just normal Unix file semantics: there is no position associated with a file, but instead positions are associated with file descriptors, and each file descriptor pointing to the same file has its own position, independent of the current size of the file. When you truncate the file outside of mongod, that does not change the position of the file descriptor that mongod has open to write the file. After truncating the file mongod will continue to writing to that file descriptor, at the position associated with its file descriptor; but since the file size is now less than position it is writing at, there will be a "hole" in the file from the beginning of the file to the position associated with mongod's file descriptor, and that hole will be filled with nulls. You can replicate the same behavior by replacing mongod with another program that writes to a file, e.g.

yes >path-to-mongod.log

and then truncating the file.

In short, it is not valid to modify the log file while mongod has it open for writing, and doing so will produce undefined results.

Generated at Thu Feb 08 05:30:40 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.