Failure to connect to MongoDB after Olive -> Palm update

Per Ivo on this thread I’m now trying one-step-at-a-time upgrading of my Lilac instance to Palm. I got it up to Olive, but then I get the following error on Olive → Palm “tutor local launch”

[+] Creating 2/0
 ✔ Container tutor_local-permissions-1  Created                                                                                                                                                                                                        0.0s 
 ✔ Container tutor_local-mysql-1        Running                                                                                                                                                                                                        0.0s 
[+] Running 2/1
 ✔ Container tutor_local-permissions-1  Started                                                                                                                                                                                                        0.7s 
 ✔ Container tutor_local-mongodb-1      Started                                                                                                                                                                                                        0.0s 
2023/10/10 12:38:24 Ready: tcp://mysql:3306.
2023/10/10 12:38:24 Waiting for tcp://mongodb:27017: dial tcp 172.18.0.12:27017: connect: connection refused.
2023/10/10 12:38:25 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/10/10 12:38:26 Waiting for tcp://mongodb:27017: dial tcp 172.18.0.12:27017: connect: connection refused.
2023/10/10 12:38:27 Waiting for tcp://mongodb:27017: dial tcp 172.18.0.12:27017: connect: connection refused.
2023/10/10 12:38:28 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/10/10 12:38:44 Waiting for tcp://mongodb:27017: dial tcp 172.18.0.12:27017: i/o timeout.
2023/10/10 12:38:44 Failed to wait: timed out: tcp://mongodb:27017.
Error: Command failed with status 123: 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 -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.jobs.yml run --rm lms-job sh -e -c dockerize -wait tcp://mysql:3306 -timeout 20s
dockerize -wait tcp://mongodb:27017 -timeout 20s

How can I work around this?

The lms-job container is attempting to reach the mongodb container, and that is failing. What are the logs from the mongodb container? tutor local logs --tail=100 mongodb

Things like this:

tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:31.527+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."}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:31.527+00:00"},"s":"I",  "c":"STORAGE",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":1,"port":27017,"dbPath":"/data/db","architecture":"64-bit","host":"78957a1c9f91"}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:31.527+00:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"4.4.22","gitVersion":"fc832685b99221cffb1f5bb5a4ff5ad3e1c416b2","openSSLVersion":"OpenSSL 1.1.1f  31 Mar 2020","modules":[],"allocator":"tcmalloc","environment":{"distmod":"ubuntu2004","distarch":"x86_64","target_arch":"x86_64"}}}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:31.527+00:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"20.04"}}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:31.528+00:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"*"},"storage":{"engine":"wiredTiger","journal":{"enabled":false}}}}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:31.529+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"]}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:31.529+00:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=7479M,session_max=33000,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,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],,log=(enabled=false),"}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:32.203+00:00"},"s":"W",  "c":"STORAGE",  "id":22347,   "ctx":"initandlisten","msg":"Failed to start up WiredTiger under any compatibility version. This may be due to an unsupported upgrade or downgrade."}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:32.203+00:00"},"s":"F",  "c":"STORAGE",  "id":28595,   "ctx":"initandlisten","msg":"Terminating.","attr":{"reason":"95: Operation not supported"}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:32.203+00:00"},"s":"F",  "c":"-",        "id":23091,   "ctx":"initandlisten","msg":"Fatal assertion","attr":{"msgid":28595,"file":"src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp","line":958}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:32.203+00:00"},"s":"F",  "c":"-",        "id":23092,   "ctx":"initandlisten","msg":"\n\n***aborting after fassert() failure\n\n"}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.120+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'"}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.122+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."}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.122+00:00"},"s":"I",  "c":"STORAGE",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":1,"port":27017,"dbPath":"/data/db","architecture":"64-bit","host":"78957a1c9f91"}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.123+00:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"4.4.22","gitVersion":"fc832685b99221cffb1f5bb5a4ff5ad3e1c416b2","openSSLVersion":"OpenSSL 1.1.1f  31 Mar 2020","modules":[],"allocator":"tcmalloc","environment":{"distmod":"ubuntu2004","distarch":"x86_64","target_arch":"x86_64"}}}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.123+00:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"20.04"}}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.123+00:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"*"},"storage":{"engine":"wiredTiger","journal":{"enabled":false}}}}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.123+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"]}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.123+00:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=7479M,session_max=33000,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,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],,log=(enabled=false),"}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.805+00:00"},"s":"W",  "c":"STORAGE",  "id":22347,   "ctx":"initandlisten","msg":"Failed to start up WiredTiger under any compatibility version. This may be due to an unsupported upgrade or downgrade."}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.805+00:00"},"s":"F",  "c":"STORAGE",  "id":28595,   "ctx":"initandlisten","msg":"Terminating.","attr":{"reason":"95: Operation not supported"}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.805+00:00"},"s":"F",  "c":"-",        "id":23091,   "ctx":"initandlisten","msg":"Fatal assertion","attr":{"msgid":28595,"file":"src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp","line":958}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:39.805+00:00"},"s":"F",  "c":"-",        "id":23092,   "ctx":"initandlisten","msg":"\n\n***aborting after fassert() failure\n\n"}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.001+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'"}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.002+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."}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.003+00:00"},"s":"I",  "c":"STORAGE",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":1,"port":27017,"dbPath":"/data/db","architecture":"64-bit","host":"78957a1c9f91"}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.003+00:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"4.4.22","gitVersion":"fc832685b99221cffb1f5bb5a4ff5ad3e1c416b2","openSSLVersion":"OpenSSL 1.1.1f  31 Mar 2020","modules":[],"allocator":"tcmalloc","environment":{"distmod":"ubuntu2004","distarch":"x86_64","target_arch":"x86_64"}}}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.003+00:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"20.04"}}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.003+00:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"*"},"storage":{"engine":"wiredTiger","journal":{"enabled":false}}}}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.006+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"]}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.006+00:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=7479M,session_max=33000,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,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],,log=(enabled=false),"}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.689+00:00"},"s":"W",  "c":"STORAGE",  "id":22347,   "ctx":"initandlisten","msg":"Failed to start up WiredTiger under any compatibility version. This may be due to an unsupported upgrade or downgrade."}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.689+00:00"},"s":"F",  "c":"STORAGE",  "id":28595,   "ctx":"initandlisten","msg":"Terminating.","attr":{"reason":"95: Operation not supported"}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.689+00:00"},"s":"F",  "c":"-",        "id":23091,   "ctx":"initandlisten","msg":"Fatal assertion","attr":{"msgid":28595,"file":"src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp","line":958}}
tutor_local-mongodb-1  | {"t":{"$date":"2023-10-10T12:56:53.689+00:00"},"s":"F",  "c":"-",        "id":23092,   "ctx":"initandlisten","msg":"\n\n***aborting after fassert() failure\n\n"}

I also had the same error when trying to upgrade from 15.3.7 to 16.0.0 or 15.3.7 to 16.1.1. Unfortunately, I didn’t capture the MongoDB container logs. I restored 15.3.7 because of a lack of time to explore the problem further. Until this post, I was sure it was something specific to my box.

2023/08/17 09:38:35 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/08/17 09:38:36 Failed to wait: timed out: tcp://mongodb:27017.
Error: Command failed with status 123: docker compose -f /home/user/.local/share/tutor/env/local/docker-compose.yml -f /home/user/.local/share/tutor/env/local/docker-compose.prod.yml --project-name tutor_local -f /home/user/.local/share/tutor/env/local/docker-compose.jobs.yml run --rm lms-job sh -e -c dockerize -wait tcp://mysql:3306 -timeout 20s
dockerize -wait tcp://mongodb:27017 -timeout 20s

it’s been a while now since I last did the full upgrade path, so I can’t remember the specific versions, but was likely as Tony suggests. If memory serves me right then on those versions that kept failing I just skipped iteratively to the next versions until I got up to latest, so far everything seems to be working for me on latest build. Make sure you have the latest version of docker from the appropriate repo as well

1 Like

Thanks, @joel.edwards! To confirm, I upgraded Tutor v15.3.7 to v16.1.3 without any problem following the upgrade instructions. Whatever caused the Failed to wait: timed out: tcp://mongodb:27017 upgrade error is no longer a problem in Tutor v16.1.3. :tada:

tutor local stop
sudo rsync -avr "$(tutor config printroot)"/ /tmp/tutor-backup/
pip install --upgrade "tutor[full]"
tutor config save
tutor images build all # list the images that should be rebuilt here
tutor local upgrade --from=olive
tutor local launch

This doesn’t seem to be the case for me. I did a step-by-step upgrade, and I failed to upgrade to v16.1.8, and now I’m working backwards to try and find something that works. Nothing before 16.1.3 can be used because of a py2neo removal. But I get the exact same problem as before in that it can’t connect to mongodb when trying to tutor local launch with tutor 6.1.3…

2023/12/15 23:58:27 Ready: tcp://mysql:3306.
2023/12/15 23:58:27 Waiting for tcp://mongodb:27017: dial tcp 172.18.0.6:27017: connect: connection refused.
2023/12/15 23:58:29 Waiting for tcp://mongodb:27017: dial tcp 172.18.0.6:27017: connect: connection refused.
2023/12/15 23:58:30 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:31 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:32 Waiting for tcp://mongodb:27017: dial tcp 172.18.0.6:27017: connect: connection refused.
2023/12/15 23:58:33 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:34 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:35 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:36 Waiting for tcp://mongodb:27017: dial tcp 172.18.0.6:27017: connect: connection refused.
2023/12/15 23:58:37 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:38 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:39 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:40 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:41 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:42 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:43 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:44 Waiting for tcp://mongodb:27017: dial tcp 172.18.0.6:27017: connect: connection refused.
2023/12/15 23:58:45 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:46 Waiting for tcp://mongodb:27017: dial tcp: lookup mongodb on 127.0.0.11:53: server misbehaving.
2023/12/15 23:58:47 Failed to wait: timed out: tcp://mongodb:27017.
Error: Command failed with status 123: 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 -f /home/ubuntu/.local/share/tutor/env/local/docker-compose.jobs.yml run --rm lms-job sh -e -c dockerize -wait tcp://mysql:3306 -timeout 20s

Bumping this just because I’m betting few people were looking at the forums before the holidays, and I’m stuck and unable to update one of my Open edX servers :-/