Fixing `Error: Authentication failed.` on a previously perfectly running MongoDB server
Today after an update to Linux and a reboot, I became unable to authenticate on my MongoDB server.
If you don't care about the details you can skip and read the TLDR below.
It went like this:
# mongo
MongoDB shell version v3.6.21
connecting to: mongodb://127.0.0.1:27017/?gssapiServiceName=mongodb
Implicit session: session { "id" : UUID("facc876b-82e0-409e-bf99-864b1a415609") }
MongoDB server version: 3.6.21
> use my_db
> db.auth([username], [password])
Error: Authentication failed.
0
>
What happened? Did my database get corrupted?...
I opened the MongDB logs (tail -f /var/log/mongodb/mongod.log) and restarted the server (systemctl restart mongod) and got this wall of logs:
2020-12-02T01:07:08.005+0000 I CONTROL [main] ***** SERVER RESTARTED *****
2020-12-02T01:07:08.024+0000 I CONTROL [initandlisten] MongoDB starting : pid=2216 port=27017 dbpath=/var/lib/mongodb 64-bit host=[hostname]
2020-12-02T01:07:08.024+0000 I CONTROL [initandlisten] db version v3.6.21
2020-12-02T01:07:08.024+0000 I CONTROL [initandlisten] git version: 1cd2db51dce4b16f4bc97a75056269df0dc0bddb
2020-12-02T01:07:08.024+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.2n 7 Dec 2017
2020-12-02T01:07:08.024+0000 I CONTROL [initandlisten] allocator: tcmalloc
2020-12-02T01:07:08.024+0000 I CONTROL [initandlisten] modules: none
2020-12-02T01:07:08.024+0000 I CONTROL [initandlisten] build environment:
2020-12-02T01:07:08.024+0000 I CONTROL [initandlisten] distmod: ubuntu1604
2020-12-02T01:07:08.024+0000 I CONTROL [initandlisten] distarch: x86_64
2020-12-02T01:07:08.024+0000 I CONTROL [initandlisten] target_arch: x86_64
2020-12-02T01:07:08.025+0000 I CONTROL [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "127.0.0.1", port: 27017 }, processManagement: { timeZoneInfo: "/usr/share/zoneinfo" }, storage: { dbPath: "/var/lib/mongodb", journal: { enabled: true } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log" } }
2020-12-02T01:07:08.025+0000 I STORAGE [initandlisten] exception in initAndListen: DBPathInUse: Unable to lock the lock file: /var/lib/mongodb/mongod.lock (Resource temporarily unavailable). Another mongod instance is already running on the /var/lib/mongodb directory, terminating
2020-12-02T01:07:08.025+0000 F - [initandlisten] Invariant failure globalStorageEngine src/mongo/db/service_context_d.cpp 272
2020-12-02T01:07:08.025+0000 F - [initandlisten] \n\n***aborting after invariant() failure\n\n
2020-12-02T01:07:08.037+0000 F - [initandlisten] Got signal: 6 (Aborted).
0x55dd778a8d11 0x55dd778a7f29 0x55dd778a840d 0x7f4829331980 0x7f4828f6cfb7 0x7f4828f6e921 0x55dd75f54dc0 0x55dd76205288 0x55dd77747d61 0x55dd77743e47 0x55dd75fce851 0x55dd778a0885 0x55dd75f563d4 0x55dd75eef07c 0x55dd75fd5753 0x55dd75f57339 0x7f4828f4fbf7 0x55dd75fbd9b9
----- BEGIN BACKTRACE -----
{"backtrace":[{"b":"55DD755B6000","o":"22F2D11","s":"_ZN5mongo15printStackTraceERSo"},{"b":"55DD755B6000","o":"22F1F29"},{"b":"55DD755B6000","o":"22F240D"},{"b":"7F482931F000","o":"12980"},{"b":"7F4828F2E000","o":"3EFB7","s":"gsignal"},{"b":"7F4828F2E000","o":"40921","s":"abort"},{"b":"55DD755B6000","o":"99EDC0","s":"_ZN5mongo12verifyFailedEPKcS1_j"},{"b":"55DD755B6000","o":"C4F288","s":"_ZN5mongo20ServiceContextMongoD9_newOpCtxEPNS_6ClientEj"},{"b":"55DD755B6000","o":"2191D61","s":"_ZN5mongo14ServiceContext20makeOperationContextEPNS_6ClientE"},{"b":"55DD755B6000","o":"218DE47","s":"_ZN5mongo6Client20makeOperationContextEv"},{"b":"55DD755B6000","o":"A18851"},{"b":"55DD755B6000","o":"22EA885"},{"b":"55DD755B6000","o":"9A03D4","s":"_ZN5mongo8shutdownENS_8ExitCodeERKNS_16ShutdownTaskArgsE"},{"b":"55DD755B6000","o":"93907C","s":"_ZZN5mongo13duration_castINS_8DurationISt5ratioILl1ELl1000EEEES2_ILl1ELl1EEEET_RKNS1_IT0_EEENKUlvE_clEv"},{"b":"55DD755B6000","o":"A1F753","s":"_ZN5mongo11mongoDbMainEiPPcS1_"},{"b":"55DD755B6000","o":"9A1339","s":"main"},{"b":"7F4828F2E000","o":"21BF7","s":"__libc_start_main"},{"b":"55DD755B6000","o":"A079B9","s":"_start"}],"processInfo":{ "mongodbVersion" : "3.6.21", "gitVersion" : "1cd2db51dce4b16f4bc97a75056269df0dc0bddb", "compiledModules" : [], "uname" : { "sysname" : "Linux", "release" : "4.15.0-124-generic", "version" : "#127-Ubuntu SMP Fri Nov 6 10:54:43 UTC 2020", "machine" : "x86_64" }, "somap" : [ { "b" : "55DD755B6000", "elfType" : 3, "buildId" : "A43721619F38ECCCF865593B38977EBB8CA06224" }, { "b" : "7FFC961AE000", "path" : "linux-vdso.so.1", "elfType" : 3, "buildId" : "2F65AB6DA6CED1362D99E2FD4939F338194673AC" }, { "b" : "7F482A5AC000", "path" : "/lib/x86_64-linux-gnu/libresolv.so.2", "elfType" : 3, "buildId" : "3D39CDDB9265E8DD55E354DA80F9CD219DB3FB28" }, { "b" : "7F482A168000", "path" : "/usr/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", "elfType" : 3, "buildId" : "4778D155198D2C078070C118F6C2A15E75D7C75F" }, { "b" : "7F4829F00000", "path" : "/usr/lib/x86_64-linux-gnu/libssl.so.1.0.0", "elfType" : 3, "buildId" : "4167AEDD060DA4C48A3221FDEEFBE42FEA3D1CC2" }, { "b" : "7F4829CFC000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "2568A7F2BACBB283FA3F5ED6B68133409C9DAD31" }, { "b" : "7F4829AF4000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "51D903A839765BFA7A3AE4B5E6A73EA8E71BC129" }, { "b" : "7F4829756000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "5F1BA80882969AE923E63130BE993DE80B4551ED" }, { "b" : "7F482953E000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "679F3AE11120EC7C483BC9295345D836F5C104F7" }, { "b" : "7F482931F000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "AE13B309B7DE1CC2B1CBC7605FC174DAC01A90FC" }, { "b" : "7F4828F2E000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "CC6DD208D3AF4BC505F599A90EF8AF52F16116E4" }, { "b" : "7F482A7C6000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "0A5772E6599F66B61B7851DB8EB10D257F4C1993" } ] }}
mongod(_ZN5mongo15printStackTraceERSo+0x41) [0x55dd778a8d11]
mongod(+0x22F1F29) [0x55dd778a7f29]
mongod(+0x22F240D) [0x55dd778a840d]
libpthread.so.0(+0x12980) [0x7f4829331980]
libc.so.6(gsignal+0xC7) [0x7f4828f6cfb7]
libc.so.6(abort+0x141) [0x7f4828f6e921]
mongod(_ZN5mongo12verifyFailedEPKcS1_j+0x0) [0x55dd75f54dc0]
mongod(_ZN5mongo20ServiceContextMongoD9_newOpCtxEPNS_6ClientEj+0x158) [0x55dd76205288]
mongod(_ZN5mongo14ServiceContext20makeOperationContextEPNS_6ClientE+0x41) [0x55dd77747d61]
mongod(_ZN5mongo6Client20makeOperationContextEv+0x27) [0x55dd77743e47]
mongod(+0xA18851) [0x55dd75fce851]
mongod(+0x22EA885) [0x55dd778a0885]
mongod(_ZN5mongo8shutdownENS_8ExitCodeERKNS_16ShutdownTaskArgsE+0x381) [0x55dd75f563d4]
mongod(_ZZN5mongo13duration_castINS_8DurationISt5ratioILl1ELl1000EEEES2_ILl1ELl1EEEET_RKNS1_IT0_EEENKUlvE_clEv+0x0) [0x55dd75eef07c]
mongod(_ZN5mongo11mongoDbMainEiPPcS1_+0x273) [0x55dd75fd5753]
mongod(main+0x9) [0x55dd75f57339]
libc.so.6(__libc_start_main+0xE7) [0x7f4828f4fbf7]
mongod(_start+0x29) [0x55dd75fbd9b9]
----- END BACKTRACE -----
Welcome to the world of Linux. What usually works unexpectedly doesn't anymore. And to troubleshoot it, you have to find the needle in the haystack. The important information in here is:
DBPathInUse: Unable to lock the lock file: /var/lib/mongodb/mongod.lock (Resource temporarily unavailable). Another mongod instance is already running on the /var/lib/mongodb directory, terminating
After deleting this file (rm /var/lib/mongodb/mongod.lock) and starting again, I get another wall of text, and this time the important information is this:
Failed to set up listener: SocketException: Address already in use
So I check open ports and get this list:
# netstat -tulpn
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
tcp 0 0 127.0.0.1:27017 0.0.0.0:* LISTEN 1151/mongod
tcp 0 0 127.0.0.53:53 0.0.0.0:* LISTEN 622/systemd-resolve
tcp 0 0 0.0.0.0:22 0.0.0.0:* LISTEN 1103/sshd
tcp6 0 0 :::80 :::* LISTEN 1180/apache2
tcp6 0 0 :::22 :::* LISTEN 1103/sshd
tcp6 0 0 :::3000 :::* LISTEN 1422/node
tcp6 0 0 :::443 :::* LISTEN 1180/apache2
udp 0 0 127.0.0.53:53 0.0.0.0:* 622/systemd-resolve
Not sure what happened to that very first instance who managed to run but not initialize correctly. I kill it (kill 1151) and try restarting MongoDB again. This time the error is:
Failed to unlink socket file /tmp/mongodb-27017.sock Operation not permitted
So I delete this file too (rm /tmp/mongodb-27017.sock) and try yet again. This time it runs and tells me:
** WARNING: Access control is not enabled for the database. Read and write access to data and configuration is unrestricted.
Waaaaaait. Does it mean that upon restart, the MongoDB daemon started with authentication disabled, and so, any attempt to authenticate would fail?
According to the official MongoDB tutorial on authentication, this option is disabled by default. So I open the config vim /etc/mongod.conf and add the setting as instructed:
security:
authorization: enabled
I restart a final time and this time, it initializes without any warning. I try to authenticate and it works. Phew!
So I try to authenticate once again and... Same error! Authentication failed. What??? So I check the command history to get a grasp of what I did back then. It looks like I had changed the db path to /data/db but didn't change the conf file. Wow. So I update /etc/mongod.conf and run again. This time it works and I can finally authenticate.
TLDR
So what happened was:
- I manually ran MongoDB with authentication enabled with a non-default path to the database.
- Upon restart the server used an empty database.
- Any attempt to authenticate failed.
- Changed the MongoDB config to enable authentication and to use the non-default path.
- Restarted the server with authentication enabled.