[SERVER-31596] recovery messages always appear in the log, even after clean shutdown Created: 17/Oct/17  Updated: 27/Oct/23  Resolved: 18/Oct/17

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

Type: Bug Priority: Major - P3
Reporter: Eric Milkie Assignee: Susan LoVerso
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

1. Run mongod on an empty data directory.
2. Shut down mongod cleanly.
3. Restart mongod and note system log messages.

Participants:

 Description   

If I shut down a mongod cleanly and restart it, I always see these messages appear in the log:

2017-10-16T23:20:51.470-0400 I STORAGE  [initandlisten] WiredTiger message [1508210451:470968][12311:0x7fab9e63c480], txn-recover: Main recovery loop: starting at 17/4992
2017-10-16T23:20:51.520-0400 I STORAGE  [initandlisten] WiredTiger message [1508210451:520816][12311:0x7fab9e63c480], txn-recover: Recovering log 17 through 18
2017-10-16T23:20:51.521-0400 I STORAGE  [initandlisten] WiredTiger message [1508210451:521173][12311:0x7fab9e63c480], txn-recover: Recovering log 18 through 18

(I noticed them appearing in our jstest output.)
Is this expected? Something may have changed recently to cause the "17 through 18" message to always appear. The original ticket that turned on verbosity was SERVER-16796, but I don't think the messages appeared back then; something changed more recently.



 Comments   
Comment by Susan LoVerso [ 18/Oct/17 ]

I'm going to resolve this as working as expected. Please re-open if you disagree.

Comment by Susan LoVerso [ 18/Oct/17 ]

The configuration to turn it on in MongoDB was added in Jan: https://github.com/mongodb/mongo/commit/9ef439f18536ec11af418602880359438ab84c64
and it was not backported to 3.4, even though the WiredTiger changes supporting it were backported. The messages appear anytime the verbose=(recovery_progress) setting is turned on. If I add that to the mongod command line in 3.4 with --wiredTigerEngineConfigString=',verbose=(recovery_progress)' then I see them there too on restart after a clean shutdown.

WiredTiger recovery is run on every startup. A clean shutdown allows us to skip the full checkpoint that recovery forces, but we do go through the WT log. In the case of clean shutdown, when we checkpoint on close, that should be really, really fast as we have nothing to apply.

Comment by Eric Milkie [ 18/Oct/17 ]

I don't believe so.

Comment by Bruce Lucas (Inactive) [ 17/Oct/17 ]

Any possible connection to SERVER-31574?

Comment by Eric Milkie [ 17/Oct/17 ]

Possibly related: WT-3440

Generated at Thu Feb 08 04:27:35 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.