MongoDB Error when upgrading from tutor 17 to 18

Site Operators Tutor Help
, ,
1

Hello,

I am facing a MongoDB error when trying to upgrade a local tutor installation (Quince to Redwood).

Current configuration:

tutor, version 17.0.6
Docker version 27.2.0, build 3ab4256
Docker Compose version v2.29.2

I then follow the steps of the documentation:

pip install --upgrade "tutor[full]"
tutor local launch

After few steps, the upgrade stops and returns the following error:

============================================
        Upgrading MongoDb to v5.0.26
============================================
Environment generated in /home/ubuntu/.local/share/tutor/env
docker compose -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.yml -f /home/ubuntu/.local/share/tutor/env/dev/docker-compose.yml --project-name tutor_dev stop
docker compose -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.yml -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.prod.yml --project-name tutor_local up --remove-orphans -d mongodb
[+] Running 10/10
 ✔ mongodb Pulled                                                                                                                                            11.6s 
   ✔ 9ea8908f4765 Already exists                                                                                                                              0.0s 
   ✔ aef777460504 Pull complete                                                                                                                               0.4s 
   ✔ 0932d6ea02f1 Pull complete                                                                                                                               0.7s 
   ✔ 82423dbc00ad Pull complete                                                                                                                               0.9s 
   ✔ 55a38b4d380f Pull complete                                                                                                                               0.9s 
   ✔ 1466142e9a50 Pull complete                                                                                                                               1.0s 
   ✔ 6e918bfb6038 Pull complete                                                                                                                               9.9s 
   ✔ 279b88548cef Pull complete                                                                                                                              10.0s 
 ✔ permissions Pulled                                                                                                                                         1.3s 
[+] Running 2/2
 ✔ Container tutor_local-permissions-1  Started                                                                                                               1.0s 
 ✔ Container tutor_local-mongodb-1      Started                                                                                                               1.3s 
Waiting for mongodb to boot...
docker compose -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.yml -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.prod.yml --project-name tutor_local exec mongodb mongo --eval 'db.adminCommand({'"'"'setFeatureCompatibilityVersion'"'"': '"'"'5.0'"'"'})'
MongoDB shell version v5.0.26
connecting to: mongodb://127.0.0.1:27017/?compressors=disabled&gssapiServiceName=mongodb
Error: couldn't connect to server 127.0.0.1:27017, connection attempt failed: SocketException: Error connecting to 127.0.0.1:27017 :: caused by :: Connection refused :
connect@src/mongo/shell/mongo.js:372:17
@(connect):2:6
exception: connect failed
exiting with code 1
Error: Command failed with status 1: docker compose -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.yml -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.prod.yml --project-name tutor_local exec mongodb mongo --eval db.adminCommand({'setFeatureCompatibilityVersion': '5.0'})

After that, the mongo DB container keeps restarting every minute or so:

$tutor local status

tutor_local-mongodb-1         mongo:5.0.26                                      "docker-entrypoint.s…"   mongodb         10 minutes ago      Restarting (62) 13 seconds ago

Here are the mongodb logs:

$tutor local logs --tail=100 mongodb

docker compose -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.yml -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.prod.yml --project-name tutor_local logs --tail 100 mongodb
mongodb-1  | {"t":{"$date":"2024-09-01T09:52:58.917+00:00"},"s":"I",  "c":"FTDC",     "id":4784926, "ctx":"initandlisten","msg":"Shutting down full-time data capture"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:52:58.917+00:00"},"s":"I",  "c":"CONTROL",  "id":20565,   "ctx":"initandlisten","msg":"Now exiting"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:52:58.917+00:00"},"s":"I",  "c":"CONTROL",  "id":23138,   "ctx":"initandlisten","msg":"Shutting down","attr":{"exitCode":62}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.382+00:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "ctx":"-","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true}}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.384+00:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.385+00:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.385+00:00"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.387+00:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.387+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.387+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.387+00:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"main","msg":"Multi threading initialized"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.387+00:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":1,"port":27017,"dbPath":"/data/db","architecture":"64-bit","host":"2b7118cd106d"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.388+00:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.26","gitVersion":"0b4f1ea980b5380a66425a90b414106a191365f4","openSSLVersion":"OpenSSL 1.1.1f  31 Mar 2020","modules":[],"allocator":"tcmalloc","environment":{"distmod":"ubuntu2004","distarch":"x86_64","target_arch":"x86_64"}}}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.388+00:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"20.04"}}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.388+00:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"*"},"storage":{"engine":"wiredTiger"}}}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.390+00:00"},"s":"I",  "c":"STORAGE",  "id":22297,   "ctx":"initandlisten","msg":"Using the XFS filesystem is strongly recommended with the WiredTiger storage engine. See http://dochub.mongodb.org/core/prodnotes-filesystem","tags":["startupWarnings"]}
mongodb-1  | {"t":{"$date":"2024-09-01T09:53:59.390+00:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=7297M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),builtin_extension_config=(zstd=(compression_level=6)),file_manager=(close_idle_time=600,close_scan_interval=10,close_handle_minimum=2000),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.146+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:146798][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 48 through 49"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.257+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:257426][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 49 through 49"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.362+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:362782][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_ALL] Main recovery loop: starting at 48/3200 to 49/256"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.472+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:472588][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 48 through 49"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.546+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:546013][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 49 through 49"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.602+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:602137][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery log replay has successfully finished and ran for 455 milliseconds"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.602+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:602280][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_ALL] Set global recovery timestamp: (0, 0)"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.602+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:602309][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_ALL] Set global oldest timestamp: (0, 0)"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.602+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:602815][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery rollback to stable has successfully finished and ran for 0 milliseconds"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.606+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:606759][1:0x7f48ee57ac80], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 1, snapshot max: 1 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1579424"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.621+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:621262][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery checkpoint has successfully finished and ran for 18 milliseconds"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.621+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:621327][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery was completed successfully and took 475ms, including 455ms for the log replay, 0ms for the rollback to stable, and 18ms for the checkpoint."}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.623+00:00"},"s":"I",  "c":"STORAGE",  "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":1233}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.623+00:00"},"s":"I",  "c":"RECOVERY", "id":23987,   "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.633+00:00"},"s":"I",  "c":"STORAGE",  "id":22262,   "ctx":"initandlisten","msg":"Timestamp monitor starting"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.638+00:00"},"s":"W",  "c":"CONTROL",  "id":22120,   "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted","tags":["startupWarnings"]}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.643+00:00"},"s":"F",  "c":"CONTROL",  "id":20573,   "ctx":"initandlisten","msg":"Wrong mongod version","attr":{"error":"UPGRADE PROBLEM: Found an invalid featureCompatibilityVersion document (ERROR: Location4926900: Invalid featureCompatibilityVersion document in admin.system.version: { _id: \"featureCompatibilityVersion\", version: \"4.2\" }. See https://docs.mongodb.com/master/release-notes/4.4-compatibility/#feature-compatibility. :: caused by :: Invalid value for featureCompatibilityVersiondocument in admin.system.version, found 4.2, expected '4.4' or '4.9' or '5.0. See https://docs.mongodb.com/master/release-notes/4.4-compatibility/#feature-compatibility.). If the current featureCompatibilityVersion is below 4.4, see the documentation on upgrading at https://docs.mongodb.com/master/release-notes/4.4/#upgrade-procedures."}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.643+00:00"},"s":"I",  "c":"REPL",     "id":4784900, "ctx":"initandlisten","msg":"Stepping down the ReplicationCoordinator for shutdown","attr":{"waitTimeMillis":15000}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"COMMAND",  "id":4784901, "ctx":"initandlisten","msg":"Shutting down the MirrorMaestro"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"SHARDING", "id":4784902, "ctx":"initandlisten","msg":"Shutting down the WaitForMajorityService"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"NETWORK",  "id":20562,   "ctx":"initandlisten","msg":"Shutdown: going to close listening sockets"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"NETWORK",  "id":4784905, "ctx":"initandlisten","msg":"Shutting down the global connection pool"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"CONTROL",  "id":4784906, "ctx":"initandlisten","msg":"Shutting down the FlowControlTicketholder"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"-",        "id":20520,   "ctx":"initandlisten","msg":"Stopping further Flow Control ticket acquisitions."}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"CONTROL",  "id":4784908, "ctx":"initandlisten","msg":"Shutting down the PeriodicThreadToAbortExpiredTransactions"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"REPL",     "id":4784909, "ctx":"initandlisten","msg":"Shutting down the ReplicationCoordinator"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"SHARDING", "id":4784910, "ctx":"initandlisten","msg":"Shutting down the ShardingInitializationMongoD"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"REPL",     "id":4784911, "ctx":"initandlisten","msg":"Enqueuing the ReplicationStateTransitionLock for shutdown"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"-",        "id":4784912, "ctx":"initandlisten","msg":"Killing all operations for shutdown"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"-",        "id":4695300, "ctx":"initandlisten","msg":"Interrupted all currently running operations","attr":{"opsKilled":3}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"TENANT_M", "id":5093807, "ctx":"initandlisten","msg":"Shutting down all TenantMigrationAccessBlockers on global shutdown"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"COMMAND",  "id":4784913, "ctx":"initandlisten","msg":"Shutting down all open transactions"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"REPL",     "id":4784914, "ctx":"initandlisten","msg":"Acquiring the ReplicationStateTransitionLock for shutdown"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"INDEX",    "id":4784915, "ctx":"initandlisten","msg":"Shutting down the IndexBuildsCoordinator"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"REPL",     "id":4784916, "ctx":"initandlisten","msg":"Reacquiring the ReplicationStateTransitionLock for shutdown"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"REPL",     "id":4784917, "ctx":"initandlisten","msg":"Attempting to mark clean shutdown"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"NETWORK",  "id":4784918, "ctx":"initandlisten","msg":"Shutting down the ReplicaSetMonitor"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.644+00:00"},"s":"I",  "c":"SHARDING", "id":4784921, "ctx":"initandlisten","msg":"Shutting down the MigrationUtilExecutor"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.645+00:00"},"s":"I",  "c":"ASIO",     "id":22582,   "ctx":"MigrationUtil-TaskExecutor","msg":"Killing all outstanding egress activity."}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.645+00:00"},"s":"I",  "c":"COMMAND",  "id":4784923, "ctx":"initandlisten","msg":"Shutting down the ServiceEntryPoint"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.645+00:00"},"s":"I",  "c":"CONTROL",  "id":4784928, "ctx":"initandlisten","msg":"Shutting down the TTL monitor"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.645+00:00"},"s":"I",  "c":"CONTROL",  "id":4784929, "ctx":"initandlisten","msg":"Acquiring the global lock for shutdown"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.645+00:00"},"s":"I",  "c":"CONTROL",  "id":4784930, "ctx":"initandlisten","msg":"Shutting down the storage engine"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.645+00:00"},"s":"I",  "c":"STORAGE",  "id":22320,   "ctx":"initandlisten","msg":"Shutting down journal flusher thread"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.645+00:00"},"s":"I",  "c":"STORAGE",  "id":22321,   "ctx":"initandlisten","msg":"Finished shutting down journal flusher thread"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.645+00:00"},"s":"I",  "c":"STORAGE",  "id":22322,   "ctx":"initandlisten","msg":"Shutting down checkpoint thread"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.645+00:00"},"s":"I",  "c":"STORAGE",  "id":22323,   "ctx":"initandlisten","msg":"Finished shutting down checkpoint thread"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.645+00:00"},"s":"I",  "c":"STORAGE",  "id":22261,   "ctx":"initandlisten","msg":"Timestamp monitor shutting down"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.646+00:00"},"s":"I",  "c":"STORAGE",  "id":20282,   "ctx":"initandlisten","msg":"Deregistering all the collections"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.646+00:00"},"s":"I",  "c":"STORAGE",  "id":22317,   "ctx":"initandlisten","msg":"WiredTigerKVEngine shutting down"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.646+00:00"},"s":"I",  "c":"STORAGE",  "id":22318,   "ctx":"initandlisten","msg":"Shutting down session sweeper thread"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.646+00:00"},"s":"I",  "c":"STORAGE",  "id":22319,   "ctx":"initandlisten","msg":"Finished shutting down session sweeper thread"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.646+00:00"},"s":"I",  "c":"STORAGE",  "id":22324,   "ctx":"initandlisten","msg":"Closing WiredTiger in preparation for reconfiguring","attr":{"closeConfig":"leak_memory=true,"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.647+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:647161][1:0x7f48ee57ac80], close_ckpt: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 2, snapshot max: 2 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1579424"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.660+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:660932][1:0x7f48ee57ac80], WT_CONNECTION.close: [WT_VERB_RECOVERY_PROGRESS] shutdown checkpoint has successfully finished and ran for 14 milliseconds"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.661+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:660997][1:0x7f48ee57ac80], WT_CONNECTION.close: [WT_VERB_RECOVERY_PROGRESS] shutdown was completed successfully and took 14ms, including 0ms for the rollback to stable, and 14ms for the checkpoint."}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.677+00:00"},"s":"I",  "c":"STORAGE",  "id":4795905, "ctx":"initandlisten","msg":"WiredTiger closed","attr":{"durationMillis":31}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.697+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:697601][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 49 through 50"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.751+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:751529][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 50 through 50"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.845+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:845861][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_ALL] Main recovery loop: starting at 49/2048 to 50/256"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.956+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184440:956301][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 49 through 50"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.026+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:26772][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 50 through 50"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.084+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:84375][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery log replay has successfully finished and ran for 387 milliseconds"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.084+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:84511][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_ALL] Set global recovery timestamp: (0, 0)"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.084+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:84525][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_ALL] Set global oldest timestamp: (0, 0)"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.085+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:85218][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery rollback to stable has successfully finished and ran for 0 milliseconds"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.090+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:90103][1:0x7f48ee57ac80], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 1, snapshot max: 1 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1579432"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.108+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:108813][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery checkpoint has successfully finished and ran for 23 milliseconds"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.108+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:108873][1:0x7f48ee57ac80], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery was completed successfully and took 411ms, including 387ms for the log replay, 0ms for the rollback to stable, and 23ms for the checkpoint."}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.110+00:00"},"s":"I",  "c":"STORAGE",  "id":4795904, "ctx":"initandlisten","msg":"WiredTiger re-opened","attr":{"durationMillis":433}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.110+00:00"},"s":"I",  "c":"STORAGE",  "id":22325,   "ctx":"initandlisten","msg":"Reconfiguring","attr":{"newConfig":"compatibility=(release=3.3)"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.242+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:242272][1:0x7f48ee57ac80], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 2, snapshot max: 2 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1579432"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.262+00:00"},"s":"I",  "c":"STORAGE",  "id":4795903, "ctx":"initandlisten","msg":"Reconfigure complete","attr":{"durationMillis":152}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.262+00:00"},"s":"I",  "c":"STORAGE",  "id":4795902, "ctx":"initandlisten","msg":"Closing WiredTiger","attr":{"closeConfig":"leak_memory=true,"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.263+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:263579][1:0x7f48ee57ac80], close_ckpt: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 4, snapshot max: 4 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1579432"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.279+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:279856][1:0x7f48ee57ac80], WT_CONNECTION.close: [WT_VERB_RECOVERY_PROGRESS] shutdown checkpoint has successfully finished and ran for 16 milliseconds"}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.279+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1725184441:279930][1:0x7f48ee57ac80], WT_CONNECTION.close: [WT_VERB_RECOVERY_PROGRESS] shutdown was completed successfully and took 17ms, including 0ms for the rollback to stable, and 16ms for the checkpoint."}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.298+00:00"},"s":"I",  "c":"STORAGE",  "id":4795901, "ctx":"initandlisten","msg":"WiredTiger closed","attr":{"durationMillis":36}}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.298+00:00"},"s":"I",  "c":"STORAGE",  "id":22279,   "ctx":"initandlisten","msg":"shutdown: removing fs lock..."}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.299+00:00"},"s":"I",  "c":"-",        "id":4784931, "ctx":"initandlisten","msg":"Dropping the scope cache for shutdown"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.299+00:00"},"s":"I",  "c":"FTDC",     "id":4784926, "ctx":"initandlisten","msg":"Shutting down full-time data capture"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.299+00:00"},"s":"I",  "c":"CONTROL",  "id":20565,   "ctx":"initandlisten","msg":"Now exiting"}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:01.299+00:00"},"s":"I",  "c":"CONTROL",  "id":23138,   "ctx":"initandlisten","msg":"Shutting down","attr":{"exitCode":62}}

Any idea what may trigger this error ?

Thank you in advance for your help!

2

After checking the changelog, it seems that such behavior can indeed occur:

Since there have been major releases since 4.4, the upgrade will need to go through them before running Mongo 7. MongoDB would need to follow 4.4 → 5.0 → 6.0 → 7.0 upgrade path to work correctly. The container will keep on restarting with featureCompatibility error if the upgrade path is not followed.

I therefore tried to rebuild all images and run tutor local upgrade --from=quince as suggested:

To upgrade mongo, run the following command based in the appropriate environment:
tutor <dev|local|k8s> upgrade --from=quince

but the same error is triggered.

3

Hi.
If you have run upgrade --from=quince, did it upgrade successfully? What errors are you seeing in mongo logs after upgrade? Is the correct mongo version running after upgrade?

4

The same behaviour seem to happen when running the upgrade --from=quince: same error message docker compose ... mongodb ... (I did not notice any difference), and the mongodb container keeps restarting.

When the mongodb container is restarted then everything seems fine but it has version 5 and not 7.7 (and the edx platform is bugged, which is expected I guess)

5

Right. Can you add the complete logs of upgrade command? It will help in identifying where the command is going wrong.

6

Sure, here are the complete logs:

$ tutor local upgrade --from=quince
⚠️  This command only performs a partial upgrade of your Open edX platform. To perform a full upgrade, you should run `tutor local launch` (or `tutor dev launch` in development).
=====================================
        Upgrading from Quince
=====================================
============================================
        Upgrading MongoDb to v5.0.26
============================================
Environment generated in /home/ubuntu/.local/share/tutor/env
docker compose -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.yml -f /home/ubuntu/.local/share/tutor/env/dev/docker-compose.yml --project-name tutor_dev stop
docker compose -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.yml -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.prod.yml --project-name tutor_local up --remove-orphans -d mongodb
[+] Running 10/10
 ✔ mongodb Pulled                                                                                                             12.1s 
   ✔ 9ea8908f4765 Already exists                                                                                               0.0s 
   ✔ aef777460504 Pull complete                                                                                                0.4s 
   ✔ 0932d6ea02f1 Pull complete                                                                                                0.7s 
   ✔ 82423dbc00ad Pull complete                                                                                                0.8s 
   ✔ 55a38b4d380f Pull complete                                                                                                0.9s 
   ✔ 1466142e9a50 Pull complete                                                                                                0.9s 
   ✔ 6e918bfb6038 Pull complete                                                                                               10.5s 
   ✔ 279b88548cef Pull complete                                                                                               10.5s 
 ✔ permissions Pulled                                                                                                          1.3s 
[+] Running 2/2
 ✔ Container tutor_local-permissions-1  Started                                                                                0.9s 
 ✔ Container tutor_local-mongodb-1      Started                                                                                1.2s 
Waiting for mongodb to boot...
docker compose -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.yml -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.prod.yml --project-name tutor_local exec mongodb mongo --eval 'db.adminCommand({'"'"'setFeatureCompatibilityVersion'"'"': '"'"'5.0'"'"'})'
MongoDB shell version v5.0.26
connecting to: mongodb://127.0.0.1:27017/?compressors=disabled&gssapiServiceName=mongodb
Error: couldn't connect to server 127.0.0.1:27017, connection attempt failed: SocketException: Error connecting to 127.0.0.1:27017 :: caused by :: Connection refused :
connect@src/mongo/shell/mongo.js:372:17
@(connect):2:6
exception: connect failed
exiting with code 1
Error: Command failed with status 1: docker compose -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.yml -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.prod.yml --project-name tutor_local exec mongodb mongo --eval db.adminCommand({'setFeatureCompatibilityVersion': '5.0'})
7

As evident in the logs, the connection to mongo is failing. Have you done any changes to mongo container? Are you using Mongo container that comes with Tutor?

8

I am indeed using the Mongo container that comes with Tutor. I don’t remember making any change to this container (at least not willingly).

Before trying to upgrade to tutor 18, I first updated Tutor from 16.1.1 to 17.0.6 (Palm to Quince) and everything went well. But from the changelog it seems there was no MongoDB upgrade between these 2 versions so probably not very informative…

9

Any advice on how I could debug this ?
I have done few customizations to the platform (custom translations, SMTP, indigo theme), but I think none of them impacts mongo db. Any idea how I could identify the problem ?
It really feels like the mongo db container is crashing while upgrading.

Is there an alternative way to force update to 7.7 ?

10

I don’t have a definitive answer on why the container shows a connection error when upgrading. One particular error log shows the container moved to mongo 5 but feature compatibility did not change

mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.638+00:00"},"s":"W",  "c":"CONTROL",  "id":22120,   "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted","tags":["startupWarnings"]}
mongodb-1  | {"t":{"$date":"2024-09-01T09:54:00.643+00:00"},"s":"F",  "c":"CONTROL",  "id":20573,   "ctx":"initandlisten","msg":"Wrong mongod version","attr":{"error":"UPGRADE PROBLEM: Found an invalid featureCompatibilityVersion document (ERROR: Location4926900: Invalid featureCompatibilityVersion document in admin.system.version: { _id: \"featureCompatibilityVersion\", version: \"4.2\" }. See https://docs.mongodb.com/master/release-notes/4.4-compatibility/#feature-compatibility. :: caused by :: Invalid value for featureCompatibilityVersiondocument in admin.system.version, found 4.2, expected '4.4' or '4.9' or '5.0. See https://docs.mongodb.com/master/release-notes/4.4-compatibility/#feature-compatibility.). If the current featureCompatibilityVersion is below 4.4, see the documentation on upgrading at https://docs.mongodb.com/master/release-notes/4.4/#upgrade-procedures."}}

Can you try setting the feature compatibility to 5.0 manually and then try the upgrade command
tutor local exec mongodb mongo --eval 'db.adminCommand({setFeatureCompatibilityVersion: "5.0"})'?

11

I tried but I can’t: since the mongodb container keeps restarting everytime it is on, it is impossible to execute any command (even starting a basic shell does not work).

The error in the log causing the restart seems to still be the same:
Found an invalid featureCompatibilityVersion document (ERROR: Location4926900: Invalid featureCompatibilityVersion document in admin.system.version: { _id: \"featureCompatibilityVersion\", version: \"4.2\" }. See https://docs.mongodb.com/master/release-notes/4.4-compatibility/#feature-compatibility. :: caused by :: Invalid value for featureCompatibilityVersiondocument in admin.system.version, found 4.2, expected '4.4' or '4.9' or '5.0. See https://docs.mongodb.com/master/release-notes/4.4-compatibility/#feature-compatibility.). If the current featureCompatibilityVersion is below 4.4, see the documentation on upgrading at https://docs.mongodb.com/master/release-notes/4.4/#upgrade-procedures."}}

Do you think it could be due to an incomplete former upgrade of the platform ? ( admin.system.version stayed in 4.2 while the mongodb was updated to 4.4)

I tried rolling back to the latest working snapshot of the platform (tutor 17.0.6, edX Quince) and doing the all procedure again but the same bug occurs.

12

I may have found a way to bypass the problem but I am not completely sure it will work yet (I have done few tests locally but not on my server yet).

It seems that something in the files located $(tutor config printroot)/data/mongodb is causing the error. Based on the few tests I have made, the following procedure could work:

  1. Backup all databases using plugin: GitHub - hastexo/tutor-contrib-backup: This is an experimental Tutor plugin. You should not consider it ready for production use at this point., a .tar file is created in $(tutor config printroot)/env/backup/ when executing tutor local backup
  2. Replace all files in $(tutor config printroot)/data/mongodb by the default files created by tutor when installing from scratch
  3. Perform the tutor 18 upgrade (which should be fine now)
  4. Use ttutor local restore --exclude=caddy --exclude=mysql to restore the Mongo Database only

I have good reasons to believe this will work, but I’ll try and share the results in this thread.

13

I suspect it is an incomplete upgrade issue. It is good to backup data before doing any further operation. Before you delete any data, one thing you might be able to try is to move MongoDB version back to 4.4.
Stop the container, set DOCKER_IMAGE_MONGODB value to “docker.io/mongo:4.4.25”, and start mongoDB container. Verify that the mongo container is running. Then, set the featurecompatibility to 4.4 (this was the value when upgrading from olive tutor/tutor/commands/upgrade/k8s.py at 07bf0dea157548ac08d556ad8642166a64ba7afe · DawoudSheraz/tutor · GitHub)
Stop the container, unset the value, and run upgrade command. It should work because we will be running an upgrade from Mongo 4.4 and not 5.0. The featurecompatibility is set to 4.4 and should not cause issues when the container first launches with mongo 5.0.

14

In the end, the only way I manage to successfully upgrade from Tutor 17 (Quince) to Tutor 18 (Redwood) is by doing the following:

  1. Use tutor-contrib-backup-plugin to backup all databases of the Tutor 17 platform: tutor local backup (this creates a tar.gz file in $(tutor config printroot)/env/backup//env/backup)
  2. Copy all tutor files and data in another location as described in https://docs.tutor.edly.io/tutorials/datamigration.html: sudo rsync -avr $(tutor config printroot)/ ~/tmp/tutor
  3. Uninstall tutor + delete directory $(tutor config printroot)
  4. Install tutor (latest version so 18) from scratch
  5. Replace newly created tutor files in $(tutor config printroot) by the old ones backuped in ~/tmp/tutor EXCEPT the files located in "$(tutor config printroot)/data/mongodb
  6. Restore the old MongoDB data using tutor-contrib-backup-plugin: tutor local restore --exclude=caddy --exclude=mysql

I finally run:

tutor config save
tutor local launch

The platform seems to work without bugs or data loss

1 Like