Donnerstag, 22. März 2018
Ich betreibe an drei physischen Standorten auf zu Linux-Servern umfunktionierten Lenovo-Laptops je einen UniFi-Controller, um die UniFi-Access Points an diesen drei Standorten zu provisionieren und zu überwachen.
Wer diese Software ebenfalls im Einsatz hat, sollte insbesondere nach Updates gelegentlich mal in das Verzeichnis /var/log/unifi reinschauen und überprüfen, dass sich die Log-Datei mongod.log nicht im Sekundentakt mit nachfolgend aufgeführten Fehlermeldungen füllt und so locker mehrer Gigabyte gross werden kann:
2018-03-12T20:49:21.010+0100 I CONTROL [main] ***** SERVER RESTARTED *****
2018-03-12T20:49:21.018+0100 I CONTROL [initandlisten] MongoDB starting : pid=26817 port=27117 dbpath=/usr/lib/unifi/data/db 64-bit host=HOSTNAME
2018-03-12T20:49:21.018+0100 I CONTROL [initandlisten] db version v3.2.11
2018-03-12T20:49:21.018+0100 I CONTROL [initandlisten] git version: 009580ad490190ba33d1c6253ebd8d91808923e4
2018-03-12T20:49:21.018+0100 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.2l 25 May 2017
2018-03-12T20:49:21.018+0100 I CONTROL [initandlisten] allocator: tcmalloc
2018-03-12T20:49:21.018+0100 I CONTROL [initandlisten] modules: none
2018-03-12T20:49:21.018+0100 I CONTROL [initandlisten] build environment:
2018-03-12T20:49:21.018+0100 I CONTROL [initandlisten] distarch: x86_64
2018-03-12T20:49:21.018+0100 I CONTROL [initandlisten] target_arch: x86_64
2018-03-12T20:49:21.018+0100 I CONTROL [initandlisten] options: { net: { bindIp: "127.0.0.1", http: { enabled: false }, port: 27117, unixDomainSocket: { pathPrefix: "/usr/lib/unifi/run" } }, storage: { dbPath: "/usr/lib/unifi/data/db" }, systemLog: { destination: "file", logAppend: true, path: "/usr/lib/unifi/logs/mongod.log" } }
2018-03-12T20:49:21.068+0100 E NETWORK [initandlisten] listen(): bind() failed errno:98 Address already in use for socket: 127.0.0.1:27117
2018-03-12T20:49:21.069+0100 E NETWORK [initandlisten] addr already in use
2018-03-12T20:49:21.069+0100 E STORAGE [initandlisten] Failed to set up sockets during startup.
2018-03-12T20:49:21.069+0100 I CONTROL [initandlisten] dbexit: rc: 48
Relevant ist die eine Zeile, die da lautet:
2018-03-12T20:49:21.068+0100 E NETWORK [initandlisten] listen(): bind() failed errno:98 Address already in use for socket: 127.0.0.1:27117
Sie besagt, dass bereits ein Prozess auf Port 27117 lauscht. Und was macht das blöde Stück Software in einem solchen Fall? Es startet neu, immer wieder, ohne Ende. Und bei jedem Neustart (gefühlt alle Sekunde, wenn man sich mit tail -f dranhänkt) füllt sich das Log mit weiteren 1600+ Bytes und somit mit 5.6 Megabytes pro Stunde, 134.4 MB pro Tag und 940.8 MB pro Woche.
Als Anschauungsbeispiel das Log-Verzeichnis auf einem meiner Server:
/var/log/unifi]# ls -lh
total 1.2G
-rw------- 1 unifi root 0 Mar 18 00:08 mongod.log
-rw------- 1 unifi root 153 Jan 12 14:32 mongod.log.10.gz
-rw------- 1 unifi root 900 Jan 5 23:38 mongod.log.11.gz
-rw------- 1 unifi root 882 Dec 30 22:15 mongod.log.12.gz
-rw------- 1 unifi root 687 Dec 23 02:27 mongod.log.13.gz
-rw------- 1 unifi root 691 Dec 16 10:58 mongod.log.14.gz
-rw------- 1 unifi root 1.1G Dec 2 12:07 mongod.log.15.gz
-rw------- 1 unifi root 3.4M Mar 13 21:30 mongod.log.1.gz
-rw------- 1 unifi root 30M Mar 12 00:09 mongod.log.2.gz
-rw------- 1 unifi root 23M Mar 4 00:09 mongod.log.3.gz
-rw------- 1 unifi root 30M Feb 26 00:07 mongod.log.4.gz
-rw------- 1 unifi root 23M Feb 18 00:09 mongod.log.5.gz
-rw------- 1 unifi root 30M Feb 12 00:08 mongod.log.6.gz
-rw------- 1 unifi root 1.7M Feb 4 00:10 mongod.log.7.gz
-rw------- 1 unifi root 675 Jan 26 09:19 mongod.log.8.gz
-rw------- 1 unifi root 236 Jan 21 14:25 mongod.log.9.gz
Wie man auf einen Blick sieht, hat sich das Log in der Woche vom 25. November bis zum 2. Dezember auf diese Weise gefüllt und war selbst mit gzip gezippt noch satte 1.1GB gross. Im Vergleich zu anderen Wochen, wo ein paar wenige Bytes zusammenkommen.
Wer den UniFi-Controller auf einer SSD-Platte laufen hat, dem werden ob diesen Schreiboperationen die Tränen kommen.
Was ist die Lösung?
# killall mongod
Startet der UniFi-Controller die MongoDB das nächste Mal neu, kann sie sich an den Port binden.
In den Foren des Herstellers finden sich auf Anhieb eine einzige Meldungen zum Symptom, aber mit einem anderen Lösungsvorschlag, der mit meiner Situation nichts zu tun hatte:
Auf Ask Ubuntu findet sich eine generelle Problemmeldung zum Thema MongoDB: Mongod server not woking due to the following error. Von hier stammt schlussendlich der essentielle Hinweis, einfach den bereits laufenden mongodb-Prozess zu „killen“.
