[SERVER-47126] Clean dbpath when downgrading arbiters in multiversion tests Created: 26/Mar/20 Updated: 29/Oct/23 Resolved: 01/Apr/20 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | None |
| Affects Version/s: | None |
| Fix Version/s: | 4.4.0-rc0 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Luke Chen | Assignee: | Alex Cameron (Inactive) |
| Resolution: | Fixed | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||||||||||
| Operating System: | ALL | ||||||||||||||||||||
| Sprint: | Storage Engines 2020-04-06 | ||||||||||||||||||||
| Participants: | |||||||||||||||||||||
| Linked BF Score: | 47 | ||||||||||||||||||||
| Story Points: | 5 | ||||||||||||||||||||
| Description |
|
The multiversion tests on the mongo v4.4 waterfall page kept failing after the recent v4.2 WiredTiger drop (with There are other 10+ tests failed in the same task which we should investigate to understand. |
| Comments |
| Comment by Githook User [ 01/Apr/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'name': 'Alex Cameron', 'email': 'alex.cameron@10gen.com', 'username': 'tetsuo-cpp'}Message: | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 01/Apr/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'name': 'Alex Cameron', 'email': 'alex.cameron@10gen.com', 'username': 'tetsuo-cpp'}Message: | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 01/Apr/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I've created | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alexander Gorrod [ 01/Apr/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks for the update daniel.gottlieb - will you use this same ticket and the associated CR to make any changes? Or should we get the CR pushed and open a new ticket? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 31/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
alex.cameron, tess.avitabile and I talked. We're going to try and fix the test to do a clean shutdown in the desired state of rollback via refetch. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 31/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Looking into it | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alex Cameron (Inactive) [ 31/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
daniel.gottlieb | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alex Cameron (Inactive) [ 27/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
If I change the test to only use secondaries, the issue goes away so it's definitely related to arbiters. But I'm missing a piece here...
This doesn't seem to work though. In fact, I don't even get to the point where this code is exercised and the arbiter appears to get restarted (and fails) before the call to upgradeArbiters. However, if I clear the dbpath when upgrading, then it seems to work.
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 27/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I can double check, but the server code I deleted might have coped with it. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Eric Milkie [ 27/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I think I prefer the second option, delete the arbiter data files as part of downgrade; this is what we document in the downgrade instructions for users to do. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alex Cameron (Inactive) [ 27/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
milkie daniel.gottlieb After looking at the test, it is PSA configuration and I found this block in wiredtiger_kv_engine.cpp:
So the arbiter doesn't downgrade its data files (and the test doesn't blow away its dbpath). If I change the test to use a PSS configuration, it passes without a problem. What are people's thoughts on this? There are a few possibilities:
Apologies for the false alarm sue.loverso, there's nothing wrong with the log downgrade path. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alex Cameron (Inactive) [ 26/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Manually going from 4.2 -> 4.4 -> 4.2 doesn't have any issues for me. I see it hitting the same downgrade path when shutting down 4.4. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Susan LoVerso [ 26/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
FYI, milkie says it really creates under 4.2, upgrades to 4.4 and does a write or two, then downgrades back to 4.2. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Susan LoVerso [ 26/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The suggested verbose should show what 4.2 (i.e. V4) log file it creates and what log files it archives/removes. The point of the downgrade, switching log files and forcing the checkpoint is to make all "other" version log files able to be removed. alexander.gorrod mentioned that we need log before the checkpoint now with DH. I don't know if that is there is something disallowing archiving other log files. So, the verbose plus the copied directory should let us know what's going on. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alex Cameron (Inactive) [ 26/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Sorry sue.loverso, my comment was missing some information. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Susan LoVerso [ 26/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
alex.cameron once we understand what MongoDB is doing differently than my WT-only testing, we should make a test that reproduces this. The CONFIG I've been using is using timestamps and uses a small cache so the HS store is in play. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Susan LoVerso [ 26/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
alex.cameron I have a couple suggestions for debugging this through MongoDB:
You need to add that additional line (as opposed to appending it the the downgrade string) because in reconfigure the verbose options are parsed last. So if it is part of one reconfigure call, the compatibility stuff will be complete before verbose logging is enabled. Second, modify <something> (the js test? the resmoke script?) to save a copy of the database directory before the startup that gives the log version error. Then we can look at the verbose output and compare it to the log files as they were after shutdown and maybe get more understanding about the issue. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Susan LoVerso [ 26/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Ok, I found the original error you're seeing in some output:
Looking closer, I see this in the log for WiredTiger open.
Trying that myself it still works for me from the mongodb-4.2 tree:
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Susan LoVerso [ 26/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
There isn't any information about what errors you're actually seeing in here. I will describe here in detail what I did and what I'm seeing (via WiredTiger only mechanisms). Essentially, a simple printlog and metadata list test works. I have two trees:
The mongodb-4.2 branch is unchanged. In the develop branch, I only modified test/format/wts.c to issue a reconfigure call just before connection close:
Build both trees. I then run test/format with a select CONFIG, but here's one generated CONFIG that yields a useful directory (a superset of mine with other values randomly generated):
Here's the verbose logging output from the first line when we do the reconfigure call until the test completes:
The database directory looks like this:
The log files all look correct to me. The only existing log file is correct. It is log version 4:
A hexdump of the two WiredTigerPreplog files also show that both have version 4 in the header. Now, run the wt command from the mongodb-4.2 tree I built:
And listing the metadata also works:
So it does appear the basic mechanism is working. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Eric Milkie [ 26/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I think it's the latter: WT does not do all the right things, yet isn't returning an error. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Susan LoVerso [ 26/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
So are you saying that the reconfigure is returning an error? Or that WiredTiger does not do (all) the right things yet still returns success? I will take a look at this today. It seems like it should be easy to reproduce with just WiredTiger calls/tests and then trying to start up on an earlier branch. I will let you know what I find. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alex Cameron (Inactive) [ 26/Mar/20 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
vamsi.krishna alexander.gorrod daniel.gottlieb The scenario that is hitting most of the issues here is downgrading from 4.4 to 4.2. I can confirm that MongoD 4.4 reconfigures to compatibility_version=3.3 when shutting down with 4.2 FCV as expected. However, when we restart with MongoD 4.2, WiredTiger detects log files with a version of 5 (which corresponds to 4.4's compatibility_version=10.0) and errors out. I've mostly been testing with:
I've added some logging to trace what is happening when shutting down with 4.2 FCV. The reconfigure call appears to do the right thing: we realise that we're downgrading log versions and go all the way down to __logmgr_force_archive and appear to do work to force a checkpoint, write a new log file with version number 4 and blow away any old log files. So WiredTiger definitely realises that we're in a downgrade situation and attempts to downgrade the log file versions (the version numbers it thinks it is downgrading to and from look correct). I'm assuming that something in that logging machinery is interacting badly with the new durable history changes and we're not doing this successfully. I'm going to continue looking at this however, I don't anticipate that I'll find get to the bottom of this tonight since it will involve learning more about the logging subsystem. sue.loverso, if you get the chance could you please take a look at this? I suspect that you'll have a much better idea of what is going on. I also had a try of just running a MongoD instance manually but I didn't see any issues.
Shut it down, then successfully started up 4.2 with the same dbpath. I also hacked wt printlog to print the log version number and it also confirms that it is 4 after shutting down.
|