[Help]: MongoDB fails to start

[tophee]

Controller Version

v5.9.31

Describe Your Issue or Question

Could someone give me a pointer why my MongoDB isn't starting (see container log below)?

Expected Behavior

I'd expect the container (including Mongo) to start as usual

Steps to Reproduce

If I knew how what changed, I'd probably change it back and it would be fixed.

But here is what I did at a high level.

The container has been working find until last night when it ran into problems because the disk on which it writes filled up. So the first thing I did was move all the volumes to an NFS share. When I relaunched the container after migration, I realized that I had accidentally misconfigured the nfs share to map all users as root (which obviously won't work when all existing files are owned by the omada user.). So I stopped the container, fixed the nfs share <nd restarted the container.

It then had permission problems writing to some file, I think it was LAST_RAN_OMADA_VER.txt. I think it was owned by root so I wasn't sure whether that is because of the nfs misconfiguration mentioned above or because it actually does write this (and a few other files) as root. So I configured the nfs share to pass through root privileges but since the container still didn't start I figured that those files that were owned by root should probably be chowned by the omada user, so I did that. Those were some files in the db directory.

So, I am not sure whether the chowning was right or wrong, but it appears that Mongo is failing to start for some other reason, but I don't understand the logs, so I'd appreciate any pointer.

Oh, forgot to mention that I then also remembered why I didn't previously use an nfs share for the volumes: MongoDB doesn't like nfs shares and from what I read, it is highly discouraged. So I mounted additional space via iSCSI instead. The iSCSI storage works fine with another container, so I don't think the issue is there.

How You're Launching the Container

Below is my docker-compose file (used as a stack in Portainer)

version: '2.2'

services:
  omada:
    image: mbentley/omada-controller:latest
    restart: unless-stopped
    container_name: omada-controller
    network_mode: host
    volumes:
      - "/etc/localtime:/etc/localtime:ro"
      - "/etc/timezone:/etc/timezone:ro"
      - "/iscsimnt/omada/data:/opt/tplink/EAPController/data"
      - "/iscsimnt/omada/work:/opt/tplink/EAPController/work"
      - "/iscsimnt/omada/logs:/opt/tplink/EAPController/logs"
    environment:
      - MANAGE_HTTP_PORT=9088
      - MANAGE_HTTPS_PORT=8043
      - PORTAL_HTTP_PORT:=9088
      - PORTAL_HTTPS_PORT=8843
      - SHOW_SERVER_LOGS=true
      - SHOW_MONGODB_LOGS=false
      - TZ=Europe/Stockholm

Container Logs

INFO: Validating user/group (omada:omada) exists with correct UID/GID (508:508)
INFO: userland/kernel check passed
INFO: Group (omada) doesn't exist; creating
INFO: User (omada) doesn't exist; creating
INFO: Value of 'port.manager.v2' already set to 29814 in omada.properties
INFO: Value of 'port.app.discovery' already set to 27001 in omada.properties
INFO: Time zone set to 'Europe/Stockholm'
INFO: Setting 'manage.http.port' to 9088 in omada.properties
INFO: Value of 'manage.https.port' already set to 8043 in omada.properties
INFO: Value of 'portal.http.port' already set to 8088 in omada.properties
INFO: Value of 'portal.https.port' already set to 8843 in omada.properties
INFO: Value of 'port.adopt.v1' already set to 29812 in omada.properties
INFO: Value of 'port.upgrade.v1' already set to 29813 in omada.properties
INFO: Value of 'port.manager.v1' already set to 29811 in omada.properties
INFO: Value of 'port.discovery' already set to 29810 in omada.properties
WARN: Ownership not set correctly on '/opt/tplink/EAPController/properties'; setting correct ownership (omada:omada)
INFO: Version check passed; image version (5.9.31) >= the last version ran (5.9.31); writing image version to last ran file...
INFO: Starting Omada Controller as user omada
09-17-2023 16:48:51.708 INFO [main] [] c.t.s.o.s.OmadaLinuxMain(): record: start the omada controller
09-17-2023 16:48:51.717 INFO [main] [] c.t.s.o.s.OmadaLinuxMain(): record: set property finished
09-17-2023 16:48:51.723 INFO [main] [] c.t.s.o.s.OmadaLinuxMain(): record: configure log finished
09-17-2023 16:48:51.730 INFO [main] [] c.t.s.o.s.OmadaBootstrap(): record: bootstrap prepare
09-17-2023 16:48:51.739 INFO [main] [] c.t.s.o.c.o.a.b(): success to load configuration omada.properties
09-17-2023 16:48:51.741 INFO [log4j-thread] [] c.t.s.o.c.o.OmadacType(): omadacType: Local Controller
09-17-2023 16:48:51.854 INFO [main] [] c.t.s.o.s.OmadaBootstrap(): going to start local mongod.
09-17-2023 16:50:32.612 ERROR [main] [] c.t.s.f.c.FacadeUtils(): facadeMsgEnable is not enable, msg: Fail to start mongo DB server
09-17-2023 16:50:32.612 WARN [main] [] c.t.s.o.s.s.b(): Fail to start mongo DB server
09-17-2023 16:50:32.612 WARN [main] [] c.t.s.o.s.s.a(): com.tplink.smb.omada.starter.b.a: Fail to start mongo DB server
com.tplink.smb.omada.starter.b.a: Fail to start mongo DB server
	at com.tplink.smb.omada.starter.server.b.a(SourceFile:151) ~[local-starter-5.9.31.jar:5.9.31]
	at com.tplink.smb.omada.starter.server.a.e(SourceFile:74) ~[local-starter-5.9.31.jar:5.9.31]
	at com.tplink.smb.omada.starter.OmadaBootstrap.d(SourceFile:249) ~[local-starter-5.9.31.jar:5.9.31]
	at com.tplink.smb.omada.starter.OmadaBootstrap.q(SourceFile:329) ~[local-starter-5.9.31.jar:5.9.31]
	at com.tplink.smb.omada.starter.OmadaBootstrap.a(SourceFile:116) ~[local-starter-5.9.31.jar:5.9.31]
	at com.tplink.smb.omada.starter.OmadaBootstrap.e(SourceFile:278) ~[local-starter-5.9.31.jar:5.9.31]
	at com.tplink.smb.omada.starter.OmadaLinuxMain.a(SourceFile:92) ~[local-starter-5.9.31.jar:5.9.31]
	at com.tplink.smb.omada.starter.OmadaLinuxMain.main(SourceFile:42) ~[local-starter-5.9.31.jar:5.9.31]
09-17-2023 16:52:14.949 ERROR [main] [] c.t.s.f.c.FacadeUtils(): facadeMsgEnable is not enable, msg: Fail to start mongo DB server
09-17-2023 16:52:14.949 WARN [main] [] c.t.s.o.s.s.b(): Fail to start mongo DB server
09-17-2023 16:52:14.949 WARN [main] [] c.t.s.o.s.s.a(): com.tplink.smb.omada.starter.b.a: Fail to start mongo DB server
	at com.tplink.smb.omada.starter.OmadaBootstrap.n(SourceFile:242) ~[local-starter-5.9.31.jar:5.9.31]
	at com.tplink.smb.omada.starter.OmadaBootstrap.q(SourceFile:332) ~[local-starter-5.9.31.jar:5.9.31]
09-17-2023 16:52:26.955 INFO [mongo-check-thread] [] c.t.s.o.s.OmadaBootstrap(): mongod was shutdown, restarting it
09-17-2023 16:52:26.991 ERROR [mongo-check-thread] [] c.t.s.f.c.FacadeUtils(): facadeMsgEnable is not enable, msg: An unexpected error occurred in MongoDb. Omada Controller will try to restart it.
09-17-2023 16:52:45.746 WARN [main] [] c.t.s.o.s.OmadaBootstrap(): Timed out after 30000 ms while waiting to connect. Client view of cluster state is {type=UNKNOWN, servers=[{address=127.0.0.1:27217, type=UNKNOWN, state=CONNECTING, exception={com.mongodb.MongoSocketOpenException: Exception opening socket}, caused by {java.net.ConnectException: Connection refused}}]
com.mongodb.MongoTimeoutException: Timed out after 30000 ms while waiting to connect. Client view of cluster state is {type=UNKNOWN, servers=[{address=127.0.0.1:27217, type=UNKNOWN, state=CONNECTING, exception={com.mongodb.MongoSocketOpenException: Exception opening socket}, caused by {java.net.ConnectException: Connection refused}}]
	at com.mongodb.internal.connection.BaseCluster.getDescription(BaseCluster.java:181) ~[mongodb-driver-core-4.4.2.jar:?]
	at com.mongodb.client.internal.MongoClientDelegate.getConnectedClusterDescription(MongoClientDelegate.java:144) ~[mongodb-driver-sync-4.4.2.jar:?]
	at com.mongodb.internal.connection.SingleServerCluster.getDescription(SingleServerCluster.java:44) ~[mongodb-driver-core-4.4.2.jar:?]
	at com.mongodb.client.internal.MongoClientDelegate.createClientSession(MongoClientDelegate.java:101) ~[mongodb-driver-sync-4.4.2.jar:?]
	at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.getClientSession(MongoClientDelegate.java:291) ~[mongodb-driver-sync-4.4.2.jar:?]
	at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:183) ~[mongodb-driver-sync-4.4.2.jar:?]
	at com.mongodb.client.internal.FindIterableImpl.first(FindIterableImpl.java:200) ~[mongodb-driver-sync-4.4.2.jar:?]
	at com.tplink.smb.omada.starter.OmadaBootstrap.a(SourceFile:645) ~[local-starter-5.9.31.jar:5.9.31]
	at com.tplink.smb.omada.starter.OmadaBootstrap.v(SourceFile:664) ~[local-starter-5.9.31.jar:5.9.31]
	at com.tplink.smb.omada.starter.OmadaBootstrap.a(SourceFile:625) ~[local-starter-5.9.31.jar:5.9.31]
	at com.tplink.smb.omada.starter.OmadaBootstrap.e(SourceFile:285) ~[local-starter-5.9.31.jar:5.9.31]
09-17-2023 16:53:15.798 ERROR [main] [] c.t.s.o.s.a(): Port 8088 is already in use.
09-17-2023 16:53:15.817 ERROR [main] [] c.t.s.o.s.a(): Port 8088 is already in use. Release the port and try again.
09-17-2023 16:53:15.818 ERROR [main] [] c.t.s.f.c.FacadeUtils(): facadeMsgEnable is not enable, msg: Port 8088 is already in use. Release the port and try again.
09-17-2023 16:53:15.819 ERROR [main] [] c.t.s.o.s.OmadaBootstrap(): Environment is not ok for controller running
09-17-2023 16:53:15.822 ERROR [main] [] c.t.s.o.s.OmadaLinuxMain(): Bootstrap prepare failed, going to exit.
09-17-2023 16:53:15.831 WARN [Thread-0] [] c.t.s.o.c.s.a(): Spring Bean Factory has not been initialed, failed to get bean class com.tplink.smb.omada.common.concurrent.thread.CommonExecutorProperties
09-17-2023 16:53:15.839 WARN [Thread-0] [] c.t.s.o.c.s.a(): Spring Bean Factory has not been initialed, failed to get bean class io.micrometer.core.instrument.MeterRegistry
Exception in thread "Thread-0" java.lang.ExceptionInInitializerError
	at com.tplink.smb.omada.common.concurrent.thread.a.a(SourceFile:85)
	at com.tplink.smb.omada.common.concurrent.thread.a.c(SourceFile:303)
	at com.tplink.smb.omada.starter.OmadaBootstrap.b(SourceFile:191)
	at com.tplink.smb.omada.starter.OmadaLinuxMain.b(SourceFile:87)
Caused by: java.lang.NullPointerException: Cannot invoke "com.tplink.smb.omada.common.concurrent.thread.CommonExecutorProperties.getCommCoreThreads()" because "com.tplink.smb.omada.common.concurrent.thread.a$b.a" is null
	at java.base/java.lang.Thread.run(Thread.java:833)
	at com.tplink.smb.omada.common.concurrent.thread.a$b.<clinit>(SourceFile:72)
	... 5 more
INFO: Group (omada) exists; skipping creation
INFO: User (omada) exists; skipping creation
INFO: Value of 'manage.http.port' already set to 9088 in omada.properties

Additional Context

No response

[mbentley]

Could you grab the MongoDB logs from /iscsimnt/omada/logs/mongod.log? That might provide more details about the reason that it isn't starting.

[tophee]

Thanks for that pointer. So stupid I didn't think about checking the MongoDB logs. (I think it was because I assumed that they were included in the container logs. I shall change the setting to make it so for the future...)

So, as I looked at the logs, it was immediately evident that there was a permissions problem:

I don't quite understand why wiredtiger_kv_engine.cpp came up there, but when I chowned the wiredtiger log file in the journal dir from root to omada, the container started as usual. Yay!

So it must really have been that nfs misconfiguration that messed up things by having the container write as root.

I was a bit hesitant to just recursively chown all of the mounted volumes because I wasn't sure whether there are any files that should not be owned by the omada user and group. So, for the record, could you clarify whether this is the case? If not, it might be worth documenting somewhere that in order to troubleshoot permission problems, you can start by doing sudo chown -R 508:508 ... or something.

While I'm at it, another quick question: When the controller comes back online, it has recently started to tell me that anything from 3 to 7 "devices on Omada Controller are connected". I have exactly 5 devices and they have always been connected without issues, regardless of how many Devices the controller message mentions, so it's not a big deal, but I'm wondering where it is getting all those extra devices from.

Until today, it used to report six devices, but now it mentioned 7 for the first time. So I have a suspicion that whenever some issues happen (like today), it somehow duplicates an item or something?

Edit/PS: I also noticed WiredTiger complaining about the filesystem (I'm using ext4). Is that an actual problem?

[mbentley]

You can safely chown all files to the equivalent of omada:omada (508:508 by default as you've indicated). Of all of my persistent data files, the only file that is not is LAST_RAN_OMADA_VER.txt which is owned by root:root because it does the checks as root during the entrypoint startup before dropping permissions.

Not sure about the messages about the number of devices - not sure I have paid attention to that. I would assume it isn't a problem assuming that it actually shows the right number once the controller is started and when you check in the user interface.

With the filesystem, I think it's just preferred the xfs is the filesystem but I am not aware of anything that doesn't function correctly with ext4. Using xfs might provide the best performance but I don't think that MongoDB performance for something a relatively simple as the controller would be a big deal.