[SERVER-37758] assert fail on fresh install Created: 25/Oct/18  Updated: 31/Oct/18  Resolved: 30/Oct/18

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

Type: Bug Priority: Major - P3
Reporter: Jeff Meredith Assignee: Danny Hatcher (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

I'm deploying a single node mongodb (4.0.3) via Kubernetes/helm (chart 4.6.2) and docker. I often, but do not always, see the system initialization fail because it does not find the `featureCompatibilityVersion` file in the container 

it is similar to an issue reported earlier this year: https://jira.mongodb.org/browse/SERVER-33362

*Welcome to the Bitnami mongodb container*
 
Subscribe to project updates by watching *https://github.com/bitnami/bitnami-docker-mongodb*
 
Submit issues and feature requests at *https://github.com/bitnami/bitnami-docker-mongodb/issues*
 
 
 
nami    INFO  Initializing mongodb
 
mongodb INFO  ==> Deploying MongoDB from scratch...
 
mongodb INFO  ==> No injected configuration files found. Creating default config files...
 
mongodb INFO  ==> Creating root user...
 
mongodb INFO  ==> Enabling authentication...
 
mongodb INFO 
 
mongodb INFO  ########################################################################
 
mongodb INFO   Installation parameters for mongodb:
 
mongodb INFO     Root Password: **********
 
mongodb INFO   (Passwords are not shown for security reasons)
 
mongodb INFO  ########################################################################
 
mongodb INFO 
 
nami    INFO  mongodb successfully initialized
 
INFO  ==> Starting mongodb... 
 
2018-10-25T22:33:43.072+0000 I CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
 
2018-10-25T22:33:43.077+0000 I CONTROL  [initandlisten] MongoDB starting : pid=82 port=27017 dbpath=/opt/bitnami/mongodb/data/db 64-bit host=vantiq-ostest-mongodb-749df5cd-cmjjp
 
2018-10-25T22:33:43.077+0000 I CONTROL  [initandlisten] db version v4.0.3
 
2018-10-25T22:33:43.077+0000 I CONTROL  [initandlisten] git version: 7ea530946fa7880364d88c8d8b6026bbc9ffa48c
 
2018-10-25T22:33:43.077+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.1.0f  25 May 2017
 
2018-10-25T22:33:43.077+0000 I CONTROL  [initandlisten] allocator: tcmalloc
 
2018-10-25T22:33:43.077+0000 I CONTROL  [initandlisten] modules: none
 
2018-10-25T22:33:43.077+0000 I CONTROL  [initandlisten] build environment:
 
2018-10-25T22:33:43.077+0000 I CONTROL  [initandlisten]     distmod: debian92
 
2018-10-25T22:33:43.077+0000 I CONTROL  [initandlisten]     distarch: x86_64
 
2018-10-25T22:33:43.077+0000 I CONTROL  [initandlisten]     target_arch: x86_64
 
2018-10-25T22:33:43.077+0000 I CONTROL  [initandlisten] options: \{ config: "/opt/bitnami/mongodb/conf/mongodb.conf", net: { bindIpAll: true, ipv6: true, port: 27017, unixDomainSocket: { enabled: true, pathPrefix: "/opt/bitnami/mongodb/tmp" } }, processManagement: \{ fork: false, pidFilePath: "/opt/bitnami/mongodb/tmp/mongodb.pid" }, security: \{ authorization: "enabled" }, setParameter: \{ enableLocalhostAuthBypass: "false" }, storage: \{ dbPath: "/opt/bitnami/mongodb/data/db", journal: { enabled: true } }, systemLog: \{ destination: "file", logAppend: true, logRotate: "reopen", path: true } }
 
2018-10-25T22:33:43.078+0000 I STORAGE  [initandlisten] Detected data files in /opt/bitnami/mongodb/data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
 
2018-10-25T22:33:43.078+0000 I STORAGE  [initandlisten] 
 
2018-10-25T22:33:43.078+0000 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
 
2018-10-25T22:33:43.078+0000 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
 
2018-10-25T22:33:43.078+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=3475M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
 
2018-10-25T22:33:44.171+0000 I STORAGE  [initandlisten] WiredTiger message [1540506824:171851][82:0x7f441ac3b9c0], txn-recover: Main recovery loop: starting at 1/9088
 
2018-10-25T22:33:44.258+0000 I STORAGE  [initandlisten] WiredTiger message [1540506824:258481][82:0x7f441ac3b9c0], txn-recover: Recovering log 1 through 2
 
2018-10-25T22:33:44.384+0000 I STORAGE  [initandlisten] WiredTiger message [1540506824:384339][82:0x7f441ac3b9c0], txn-recover: Recovering log 2 through 2
 
2018-10-25T22:33:44.421+0000 I STORAGE  [initandlisten] WiredTiger message [1540506824:421322][82:0x7f441ac3b9c0], txn-recover: Set global recovery timestamp: 0
 
2018-10-25T22:33:45.370+0000 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
 
2018-10-25T22:33:46.297+0000 W CONTROL  [initandlisten] 
 
2018-10-25T22:33:46.297+0000 W CONTROL  [initandlisten] 
 
2018-10-25T22:33:46.297+0000 I CONTROL  [initandlisten] 
 
2018-10-25T22:33:46.801+0000 F STORAGE  [initandlisten] Unable to start up mongod due to missing featureCompatibilityVersion document.
 
2018-10-25T22:33:46.801+0000 F STORAGE  [initandlisten] Please run with --repair to restore the document.
 
2018-10-25T22:33:46.802+0000 F -        [initandlisten] Fatal Assertion 40652 at src/mongo/db/repair_database_and_check_version.cpp 579
 
2018-10-25T22:33:46.802+0000 F -        [initandlisten] 
 
 
 
***aborting after fassert() failure
 
ERROR ==> error: mongod does not appear to be running -- perhaps it had an error?

It seems impossible that a freshly created install would need repair. further, when i run the deploy in isolation (nothing else deploying at the same time) it works reliably. 

 



 Comments   
Comment by Jeff Meredith [ 31/Oct/18 ]

Hi Danny,

Thanks again for your help. I changed my K8s Helm chart to use the library/mongo image in docker hub and that works great. my environment only seems to trip up when using the bitnami image. 

Comment by Danny Hatcher (Inactive) [ 30/Oct/18 ]

Hello Jeff,

I've taken a quick look through the linked GitHub pages. You are correct that this script is starting up MongoDB, seeding a root user, and then restarting the node. However, without digging into the Docker container itself, I am unsure as to how it is actually seeding the root user. In a normal MongoDB installation, once you start it up as a fresh install it will come with the correct featureCompabilityVersion document.

If you are unaware, this document was introduced in MongoDB 3.4 to ensure backwards compatibility with previous versions when going through the upgrade process. If you had a MongoDB 3.4 installation and you were upgrading to MongoDB 3.6, there were some changes in 3.6 that would not be downgradable back to 3.4. Thus, you would run 3.6 binaries but with a featureCompatibilityVersion of 3.4 in case you wanted to downgrade. When you decided that 3.6 was safe to run and you wanted the new features, you would upgrade this document to 3.6. This process continued in 4.0 and will likely continue in the foreseeable future. For more information, please see https://docs.mongodb.com/manual/reference/command/setFeatureCompatibilityVersion/index.html.

My guess is that the container is starting up an old version of MongoDB (3.2 or earlier) to seed the user and then starting up again with a new version. Because it sees data files already existing, it does not automatically create the document. But because MongoDB relies on the presence of the document to determine which features to enable, it fatally asserts.

Unfortunately, as I am unable to reproduce this and we have not had reports of this circumstance happening recently, I believe that it is almost certainly a problem with the container. I see you opened a GitHub issue with the project and I encourage you to keep following up with them.

Thanks,

Danny

Comment by Jeff Meredith [ 26/Oct/18 ]

yes, it seems creating the root user initlializes the data/db directory. i updated my script to show FS contents before and after:

  checkfs "Before init"

  nami_initialize mongodb

  checkfs "Before starting mongodb"

  info "Starting mongodb... "

the log shows the difference:

Welcome to the Bitnami mongodb container

Subscribe to project updates by watching *https://github.com/bitnami/bitnami-docker-mongodb*

Submit issues and feature requests at *https://github.com/bitnami/bitnami-docker-mongodb/issues*

 

INFO ==> Before init: mongodb files are:

total 120

rw-rw-r-. 1 root root 34520 Oct  3 08:13 GNU-AGPL-3.0

rw-rw-r-. 1 root root  2149 Oct  3 08:13 LICENSE-Community.txt

rw-rw-r-. 1 root root 16726 Oct  3 08:13 MPL-2

rw-rw-r-. 1 root root  2195 Oct  3 08:13 README

rw-rw-r-. 1 root root 57190 Oct  3 08:13 THIRD-PARTY-NOTICES

drwxrwxr-x. 2 root root   231 Oct 23 20:40 bin

drwxrwxr-x. 2 root root    31 Oct 23 20:40 licenses

nami    INFO  Initializing mongodb

mongodb INFO  ==> Deploying MongoDB from scratch...

mongodb INFO  ==> No injected configuration files found. Creating default config files...

mongodb INFO  ==> Creating root user...

mongodb INFO  ==> Enabling authentication...

mongodb INFO

mongodb INFO  ########################################################################

mongodb INFO   Installation parameters for mongodb:

mongodb INFO     Root Password: **********

mongodb INFO   (Passwords are not shown for security reasons)

mongodb INFO  ########################################################################

mongodb INFO

nami    INFO  mongodb successfully initialized

INFO ==> Before starting mongodb: db files are:

total 96

rw-rr-. 1 1001 1001    45 Oct 26 20:32 WiredTiger

rw-rr-. 1 1001 1001    21 Oct 26 20:32 WiredTiger.lock

rw-rr-. 1 1001 1001  1062 Oct 26 20:32 WiredTiger.turtle

rw-rr-. 1 1001 1001 32768 Oct 26 20:32 WiredTiger.wt

rw-rr-. 1 1001 1001  4096 Oct 26 20:32 WiredTigerLAS.wt

rw-rr-. 1 1001 1001 16384 Oct 26 20:32 _mdb_catalog.wt

rw-rr. 1 1001 1001  4096 Oct 26 20:32 collection-0-6869272262555968975.wt

rw-rr. 1 1001 1001  4096 Oct 26 20:32 index-1-6869272262555968975.wt

drwxr-xr-x. 2 1001 1001  4096 Oct 26 20:32 journal

rw-rr-. 1 1001 1001     0 Oct 26 20:32 mongod.lock

rw-rr-. 1 1001 1001 16384 Oct 26 20:32 sizeStorer.wt

rw-rr-. 1 1001 1001   114 Oct 26 20:32 storage.bson

INFO ==> Starting mongodb...

2018-10-26T20:32:29.697+0000 I CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'

2018-10-26T20:32:29.703+0000 I CONTROL  [initandlisten] MongoDB starting : pid=89 port=27017 dbpath=/opt/bitnami/mongodb/data/db 64-bit host=vantiq-ostest-mongodb-86c6b9d48c-rns59

2018-10-26T20:32:29.703+0000 I CONTROL  [initandlisten] db version v4.0.3

2018-10-26T20:32:29.703+0000 I CONTROL  [initandlisten] git version: 7ea530946fa7880364d88c8d8b6026bbc9ffa48c

2018-10-26T20:32:29.703+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.1.0f  25 May 2017

2018-10-26T20:32:29.703+0000 I CONTROL  [initandlisten] allocator: tcmalloc

2018-10-26T20:32:29.703+0000 I CONTROL  [initandlisten] modules: none

2018-10-26T20:32:29.703+0000 I CONTROL  [initandlisten] build environment:

2018-10-26T20:32:29.703+0000 I CONTROL  [initandlisten]     distmod: debian92

2018-10-26T20:32:29.703+0000 I CONTROL  [initandlisten]     distarch: x86_64

2018-10-26T20:32:29.703+0000 I CONTROL  [initandlisten]     target_arch: x86_64

2018-10-26T20:32:29.703+0000 I CONTROL  [initandlisten] options: { config: "/opt/bitnami/mongodb/conf/mongodb.conf", net: { bindIpAll: true, ipv6: true, port: 27017, unixDomainSocket:

Unknown macro: { enabled}

}, processManagement: { fork: false, pidFilePath: "/opt/bitnami/mongodb/tmp/mongodb.pid" }, security: { authorization: "enabled" }, setParameter: { enableLocalhostAuthBypass: "false" }, storage: { dbPath: "/opt/bitnami/mongodb/data/db", journal:

Unknown macro: { enabled}

}, systemLog: { destination: "file", logAppend: true, logRotate: "reopen", path: true } }

2018-10-26T20:32:29.704+0000 I STORAGE  [initandlisten] Detected data files in /opt/bitnami/mongodb/data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.

2018-10-26T20:32:29.704+0000 I STORAGE  [initandlisten]

2018-10-26T20:32:29.704+0000 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine

2018-10-26T20:32:29.704+0000 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem

2018-10-26T20:32:29.705+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=3475M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),

2018-10-26T20:32:33.744+0000 I STORAGE  [initandlisten] WiredTiger message [1540585953:744299][89:0x7f5deaa509c0], txn-recover: Main recovery loop: starting at 1/9088

2018-10-26T20:32:33.806+0000 I STORAGE  [initandlisten] WiredTiger message [1540585953:806661][89:0x7f5deaa509c0], txn-recover: Recovering log 1 through 2

2018-10-26T20:32:33.958+0000 I STORAGE  [initandlisten] WiredTiger message [1540585953:958100][89:0x7f5deaa509c0], txn-recover: Recovering log 2 through 2

2018-10-26T20:32:34.066+0000 I STORAGE  [initandlisten] WiredTiger message [1540585954:66047][89:0x7f5deaa509c0], txn-recover: Set global recovery timestamp: 0

2018-10-26T20:32:35.172+0000 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)

2018-10-26T20:32:35.821+0000 W CONTROL  [initandlisten]

2018-10-26T20:32:35.821+0000 W CONTROL  [initandlisten]

2018-10-26T20:32:35.822+0000 I CONTROL  [initandlisten]

2018-10-26T20:32:35.879+0000 F STORAGE  [initandlisten] Unable to start up mongod due to missing featureCompatibilityVersion document.

2018-10-26T20:32:35.879+0000 F STORAGE  [initandlisten] Please run with --repair to restore the document.

2018-10-26T20:32:35.880+0000 F -        [initandlisten] Fatal Assertion 40652 at src/mongo/db/repair_database_and_check_version.cpp 579

2018-10-26T20:32:35.880+0000 F -        [initandlisten]

 

***aborting after fassert() failure

It seems something isn't always squaring between bitnami initialization and mongodb.

Comment by Jeff Meredith [ 26/Oct/18 ]

Hi Daniel, thank you for your response. I did not notice that log message previously. 

I did a little more digging by adding some bash script to the top of the app-entrypoint.sh file in the mongodb image i'm deploying:

#!/bin/bash -e

. /opt/bitnami/base/functions

. /opt/bitnami/base/helpers

print_welcome_page

if [ -a /opt/bitnami/mongodb/data/db ]; then

    FILES=`ls -l /opt/bitnami/mongodb/data/db`

    info "db files are:\n${FILES}"

elif [ -a /opt/bitnami/mongodb/data ]; then

    FILES=`ls -l /opt/bitnami/mongodb/data`

    info "data files are:\n${FILES}"

elif [ -a /opt/bitnami/mongodb ]; then

    FILES=`ls -l /opt/bitnami/mongodb`

    info "mongodb files are:\n${FILES}"

elif [ -a /opt/bitnami ]; then

    FILES=`ls -l /opt/bitnami`

    info "bitnami files are:\n${FILES}"

else

    FILES=`ls -l /opt`

    info "opt files are:\n${FILES}"

fi

if [[ "$1" == "nami" && "$2" == "start" ]] || [[ "$1" == "/run.sh" ]]; then

  nami_initialize mongodb

  info "Starting mongodb... "

fi

exec tini – "$@"

I found that I get the log message you reference every time i run regardless of the contents of /opt/bitnami/mongodb; even when there is no data directory present:

Welcome to the Bitnami mongodb container

Subscribe to project updates by watching *https://github.com/bitnami/bitnami-docker-mongodb*

Submit issues and feature requests at *https://github.com/bitnami/bitnami-docker-mongodb/issues*

INFO ==> mongodb files are:

total 120

rw-rw-r-. 1 root root 34520 Oct  3 08:13 GNU-AGPL-3.0

rw-rw-r-. 1 root root  2149 Oct  3 08:13 LICENSE-Community.txt

rw-rw-r-. 1 root root 16726 Oct  3 08:13 MPL-2

rw-rw-r-. 1 root root  2195 Oct  3 08:13 README

rw-rw-r-. 1 root root 57190 Oct  3 08:13 THIRD-PARTY-NOTICES

drwxrwxr-x. 2 root root   231 Oct 23 20:40 bin

drwxrwxr-x. 2 root root    31 Oct 23 20:40 licenses

nami    INFO  Initializing mongodb

mongodb INFO  ==> Deploying MongoDB from scratch...

mongodb INFO  ==> No injected configuration files found. Creating default config files...

mongodb INFO  ==> Creating root user...

mongodb INFO  ==> Enabling authentication...

mongodb INFO

mongodb INFO  ########################################################################

mongodb INFO   Installation parameters for mongodb:

mongodb INFO     Root Password: **********

mongodb INFO   (Passwords are not shown for security reasons)

mongodb INFO  ########################################################################

mongodb INFO

nami    INFO  mongodb successfully initialized

INFO ==> Starting mongodb...

2018-10-26T18:06:36.926+0000 I CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'

2018-10-26T18:06:36.932+0000 I CONTROL  [initandlisten] MongoDB starting : pid=93 port=27017 dbpath=/opt/bitnami/mongodb/data/db 64-bit host=vantiq-ostest-mongodb-86c6b9d48c-mj6k7

2018-10-26T18:06:36.933+0000 I CONTROL  [initandlisten] db version v4.0.3

2018-10-26T18:06:36.933+0000 I CONTROL  [initandlisten] git version: 7ea530946fa7880364d88c8d8b6026bbc9ffa48c

2018-10-26T18:06:36.933+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.1.0f  25 May 2017

2018-10-26T18:06:36.933+0000 I CONTROL  [initandlisten] allocator: tcmalloc

2018-10-26T18:06:36.933+0000 I CONTROL  [initandlisten] modules: none

2018-10-26T18:06:36.933+0000 I CONTROL  [initandlisten] build environment:

2018-10-26T18:06:36.933+0000 I CONTROL  [initandlisten]     distmod: debian92

2018-10-26T18:06:36.933+0000 I CONTROL  [initandlisten]     distarch: x86_64

2018-10-26T18:06:36.933+0000 I CONTROL  [initandlisten]     target_arch: x86_64

2018-10-26T18:06:36.933+0000 I CONTROL  [initandlisten] options: { config: "/opt/bitnami/mongodb/conf/mongodb.conf", net: { bindIpAll: true, ipv6: true, port: 27017, unixDomainSocket:

Unknown macro: { enabled}

}, processManagement: { fork: false, pidFilePath: "/opt/bitnami/mongodb/tmp/mongodb.pid" }, security: { authorization: "enabled" }, setParameter: { enableLocalhostAuthBypass: "false" }, storage: { dbPath: "/opt/bitnami/mongodb/data/db", journal:

Unknown macro: { enabled}

}, systemLog: { destination: "file", logAppend: true, logRotate: "reopen", path: true } }

2018-10-26T18:06:36.933+0000 I STORAGE  [initandlisten] Detected data files in /opt/bitnami/mongodb/data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.

Further, i'm deploying lots of other stuff (postgresql, mysql, influxdb, telegraf-ds, my app, nginx etc.). i would suspect that if K8s, docker and openstack were not providing clean volumes on the first run, i would see issues in at least one of these systems. i don't. they all start cleanly every time.

Anyway, is there an explanation for why the STORAGE system is detecting previously existing data files when they do not exist at container startup? I don't believe that message is indicative of an issue with the container. Wouldn't the creation of the root user, which seems to happen earlier in the init process, need to add files to mongodb/data/db?

 

Comment by Danny Hatcher (Inactive) [ 26/Oct/18 ]

Hello Jeff,

The following line indicates that there were data files previously existing and it is not a "freshly created install".

2018-10-25T22:33:43.078+0000 I STORAGE  [initandlisten] Detected data files in /opt/bitnami/mongodb/data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.

This is most likely an issue with the container that you are using and not MongoDB itself. Unfortunately, it is not a MongoDB-provided product so I do not have further information on what the problem could be. I highly encourage you to reach out to the maintainers of that container to see if they can help you troubleshoot the problem.

Thank you,

Danny

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