It’s good to do automated backups. When you do that, add monitoring to make sure the backups are occurring successfully. In my case, I backup using Bacula. Each job creates a new .bsr file. I copy these files to another location each day. Then I monitor the dates on those files and they should all be less then a day or so old.
Edit (added 2023-08-29) This post is about upgrading net-mgmt/unifi6 to net-mgmt/unifi7 – the unifi service would not start. It was a mongodb issue. At work, we had the same issue I had in this post. We updated from unifi6-6.5.54 to unifi7-7.4.162 when moving from FreeBSD 12.3 (and an old ports tree) to FreeBSD 13.2. That included going from mongodb36-3.6.23 to mongodb44-4.4.23. Those two versions of mongo are not compatible. My solution: restore from backup. See the last couple of sections on this page for details.
The alert
I started getting alerts that the file was getting old.
FILE_AGE CRITICAL: /usr/home/rsyncer/backups/bacula-config/bsr/r730-01-fd_unifi.bsr is 300538 seconds old and 472 bytes
The backup
Looking at the Bacula job report:
FD Files Written: 0 SD Files Written: 0 FD Bytes Written: 0 (0 B) SD Bytes Written: 0 (0 B)
Nothing backed up in an incremental backup means no files have changed/been added since the last backup.
What is backed up?
I checked the Bacula configuration and found the job backs this up?
# Backup the unifi backups
FileSet {
Name = "unifi"
Ignore FileSet Changes = yes
Include {
Options {
signature=MD5
}
File = /jails/unifi01/usr/local/share/java/unifi/data/backup/autobackup
}
}
The files
Let’s look at that directory:
[11:40 r730-01 dvl ~] % sudo ls -l /jails/unifi01/usr/local/share/java/unifi/data/backup/autobackup total 3896003 -rw------- 1 975 wheel 38445504 Mar 17 20:45 autobackup_7.3.83_20230317_2045_1679085900004.unf -rw------- 1 975 wheel 38505776 Mar 18 20:45 autobackup_7.3.83_20230318_2045_1679172300003.unf -rw------- 1 975 wheel 38455520 Mar 19 20:45 autobackup_7.3.83_20230319_2045_1679258700003.unf -rw------- 1 975 wheel 38656752 Mar 20 20:45 autobackup_7.3.83_20230320_2045_1679345100004.unf ... -rw------- 1 975 wheel 41016736 May 2 20:45 autobackup_7.3.83_20230502_2045_1683060300003.unf -rw------- 1 975 wheel 40911776 May 3 20:45 autobackup_7.3.83_20230503_2045_1683146700005.unf -rw------- 1 975 wheel 40884496 May 4 20:45 autobackup_7.3.83_20230504_2045_1683233100012.unf -rw------- 1 975 wheel 40885008 May 5 20:45 autobackup_7.3.83_20230505_2045_1683319500004.unf -rw------- 1 975 wheel 8551 May 5 20:45 autobackup_meta.json
The last backup file was created on 5 May. That’s why the incrementals haven’t created a new .bsr file; nothing changed.
The system
Let’s look at recent changes:
[11:44 unifi01 dan ~] % bzgrep pkg /var/log/messages.* /var/log/messages.4.bz2:May 6 16:20:38 unifi01 pkg[64878]: readline upgraded: 8.2.0 -> 8.2.1 /var/log/messages.4.bz2:May 6 16:20:38 unifi01 pkg[64878]: libxml2 upgraded: 2.10.3_1 -> 2.10.4 /var/log/messages.4.bz2:May 6 16:20:38 unifi01 pkg[64878]: libxcb upgraded: 1.15 -> 1.15_1 /var/log/messages.4.bz2:May 6 16:20:39 unifi01 pkg[64878]: bind-tools upgraded: 9.18.12 -> 9.18.14 /var/log/messages.4.bz2:May 6 16:20:39 unifi01 pkg[64878]: libpsl upgraded: 0.21.2_2 -> 0.21.2_3 /var/log/messages.4.bz2:May 6 16:20:39 unifi01 pkg[64878]: curl reinstalled: 8.0.1 -> 8.0.1 /var/log/messages.4.bz2:May 6 16:20:39 unifi01 pkg[64878]: mysql57-client-5.7.40 deinstalled /var/log/messages.4.bz2:May 6 16:20:39 unifi01 pkg[64878]: jpeg-turbo upgraded: 2.1.4 -> 2.1.5.1 /var/log/messages.4.bz2:May 6 16:20:39 unifi01 pkg[64878]: zstd upgraded: 1.5.2_1 -> 1.5.4_2 /var/log/messages.4.bz2:May 6 16:20:39 unifi01 pkg[64878]: libdeflate upgraded: 1.17 -> 1.18 /var/log/messages.4.bz2:May 6 16:20:39 unifi01 pkg[64878]: fontconfig upgraded: 2.14.0,1 -> 2.14.2,1 /var/log/messages.4.bz2:May 6 16:20:40 unifi01 pkg[64878]: lcms2 upgraded: 2.13.1 -> 2.15_1 /var/log/messages.4.bz2:May 6 16:20:56 unifi01 pkg[64878]: openjdk11 upgraded: 11.0.18+10.1 -> 11.0.19+7.1 /var/log/messages.4.bz2:May 6 16:20:56 unifi01 pkg[64878]: snappy upgraded: 1.1.9_1 -> 1.1.10 /var/log/messages.4.bz2:May 6 16:20:56 unifi01 pkg[64878]: mongodb36-3.6.23_1 deinstalled /var/log/messages.4.bz2:May 6 16:20:56 unifi01 pkg[64878]: libcjson-1.7.15_1 installed /var/log/messages.4.bz2:May 6 16:20:56 unifi01 pkg[64878]: libcbor-0.10.2 installed /var/log/messages.4.bz2:May 6 16:20:56 unifi01 pkg[64878]: hidapi-0.13.1 installed /var/log/messages.4.bz2:May 6 16:20:56 unifi01 pkg[64878]: libunwind-20211201_2 installed /var/log/messages.4.bz2:May 6 16:20:58 unifi01 pkg[64878]: icu-73.1,1 installed /var/log/messages.4.bz2:May 6 16:20:58 unifi01 pkg[64878]: openldap26-client-2.6.4 installed /var/log/messages.4.bz2:May 6 16:20:58 unifi01 pkg[64878]: libfido2-1.13.0 installed /var/log/messages.4.bz2:May 6 16:20:59 unifi01 pkg[64878]: mysql80-client-8.0.32_2 installed /var/log/messages.4.bz2:May 6 16:20:59 unifi01 pkg[64878]: pcre2-10.42 installed /var/log/messages.4.bz2:May 6 16:20:59 unifi01 pkg[64878]: nagios-plugins reinstalled: 2.4.3,1 -> 2.4.3,1 /var/log/messages.4.bz2:May 6 16:21:04 unifi01 pkg[64878]: mongodb44-4.4.21 installed /var/log/messages.4.bz2:May 6 16:21:13 unifi01 pkg[64878]: openjdk8 upgraded: 8.362.09.1 -> 8.372.07.1_1 /var/log/messages.4.bz2:May 6 16:21:14 unifi01 pkg[64878]: nginx upgraded: 1.22.1_5,3 -> 1.24.0_3,3 /var/log/messages.4.bz2:May 6 16:21:15 unifi01 pkg[64878]: zsh upgraded: 5.9_1 -> 5.9_2 /var/log/messages.4.bz2:May 6 16:21:19 unifi01 pkg[64878]: python39 upgraded: 3.9.16_1 -> 3.9.16_2 /var/log/messages.4.bz2:May 6 16:21:31 unifi01 pkg[64878]: unifi7 upgraded: 7.3.83 -> 7.3.83_2 /var/log/messages.4.bz2:May 6 16:21:31 unifi01 pkg[64878]: pam_ssh_agent_auth upgraded: 0.10.4_1 -> 0.10.4_2 /var/log/messages.4.bz2:May 6 16:21:32 unifi01 pkg[64878]: sudo upgraded: 1.9.13 -> 1.9.13p3 /var/log/messages.4.bz2:May 6 16:21:32 unifi01 pkg[64878]: nrpe3 upgraded: 3.2.1 -> 3.2.1_1 /var/log/messages.4.bz2:May 6 16:21:32 unifi01 pkg[64878]: tmux upgraded: 3.3a -> 3.3a_1 /var/log/messages.4.bz2:May 6 17:51:00 unifi01 pkg[45305]: nrpe3-3.2.1_1 deinstalled /var/log/messages.4.bz2:May 6 18:11:44 unifi01 pkg[98878]: nrpe-4.1.0 installed [11:44 unifi01 dan ~] %
That’s a bunch of changes, the day after the backups stopped. I think we got some explaining to do.
Logs
Looking in the logs I see this when I start the unifi service.
[11:55 unifi01 dan ~] % sudo service unifi start Starting unifi. [11:56 unifi01 dan ~] % *** /usr/local/share/java/unifi/logs//server.log *** [2023-05-11T11:56:07,420]INFO tomcat - Adding basic REST API support during the startup [2023-05-11T11:56:07,976] INFO system - Tomcat startup took 965ms [2023-05-11T11:56:07,978] INFO db - Version 7.3.83 has not changed, skipping migration [2023-05-11T11:56:07,997] INFO tomcat - Adding basic REST API support during the startup [2023-05-11T11:56:13,834] INFO db - waiting for db connection... [2023-05-11T11:56:15,355] INFO db - Connecting to mongodb://localhost:27117 *** /usr/local/share/java/unifi/logs//mongod.log *** {"t":{"$date":"2023-05-11T11:56:15.004+00:00"},"s":"I", "c":"CONTROL", "id":20698, "ctx":"main","msg":"***** SERVER RESTARTED *****"} {"t":{"$date":"2023-05-11T11:56:15.007+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'"} {"t":{"$date":"2023-05-11T11:56:15.009+00:00"},"s":"I", "c":"NETWORK", "id":4648602, "ctx":"main","msg":"Implicit TCP FastOpen in use."} {"t":{"$date":"2023-05-11T11:56:15.009+00:00"},"s":"I", "c":"STORAGE", "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":90033,"port":27117,"dbPath":"/usr/local/share/java/unifi/data/db","architecture":"64-bit","host":"unifi01.int.unixathome.org"}} {"t":{"$date":"2023-05-11T11:56:15.010+00:00"},"s":"I", "c":"CONTROL", "id":23403, "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"4.4.21","gitVersion":"07fb62484a27e3e464ecdd6c746de64e53e19e56","openSSLVersion":"OpenSSL 1.1.1o-freebsd 3 May 2022","modules":[],"allocator":"system","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}} {"t":{"$date":"2023-05-11T11:56:15.010+00:00"},"s":"I", "c":"CONTROL", "id":51765, "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"FreeBSD","version":"FreeBSD 13.1-RELEASE-p6 GENERIC\n"}}} {"t":{"$date":"2023-05-11T11:56:15.010+00:00"},"s":"I", "c":"CONTROL", "id":21951, "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"127.0.0.1","port":27117,"unixDomainSocket":{"pathPrefix":"/usr/local/share/java/unifi/run"}},"processManagement":{"pidFilePath":"/usr/local/share/java/unifi/run/mongod.pid"},"storage":{"dbPath":"/usr/local/share/java/unifi/data/db","wiredTiger":{"engineConfig":{"configString":"cache_size=256M"}}},"systemLog":{"destination":"file","logAppend":true,"logRotate":"reopen","path":"/usr/local/share/java/unifi/logs/mongod.log"}}}} {"t":{"$date":"2023-05-11T11:56:15.010+00:00"},"s":"I", "c":"STORAGE", "id":22270, "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/usr/local/share/java/unifi/data/db","storageEngine":"wiredTiger"}} {"t":{"$date":"2023-05-11T11:56:15.011+00:00"},"s":"I", "c":"STORAGE", "id":22315, "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=228796M,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],cache_size=256M"}} {"t":{"$date":"2023-05-11T11:56:15.871+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."} {"t":{"$date":"2023-05-11T11:56:15.872+00:00"},"s":"F", "c":"STORAGE", "id":28595, "ctx":"initandlisten","msg":"Terminating.","attr":{"reason":"45: Operation not supported"}} {"t":{"$date":"2023-05-11T11:56:15.872+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}} {"t":{"$date":"2023-05-11T11:56:15.872+00:00"},"s":"F", "c":"-", "id":23092, "ctx":"initandlisten","msg":"\n\n***aborting after fassert() failure\n\n"} *** /usr/local/share/java/unifi/logs//server.log *** [2023-05-11T11:56:15,875] INFO db - DbServer stopped [2023-05-11T11:56:19,942] INFO db - {"t":{"$date":"2023-05-11T11:56:19.942Z"},"s":"I", "c":"STORAGE", "id":22293, "ctx":"main","msg":"Engine custom option","attr":{"option":"cache_size=256M"}} *** /usr/local/share/java/unifi/logs//mongod.log *** {"t":{"$date":"2023-05-11T11:56:19.942+00:00"},"s":"I", "c":"CONTROL", "id":20698, "ctx":"main","msg":"***** SERVER RESTARTED *****"} {"t":{"$date":"2023-05-11T11:56:19.944+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'"}
And the cycle repeats.
I think the key message is:
Failed to start up WiredTiger under any compatibility version. This may be due to an unsupported upgrade or downgrade
Looking closer, I see:
mongodb36-3.6.23_1 deinstalled May 6 16:20:56 unifi01 pkg[64878]: mongodb36-3.6.23_1 deinstalled ... May 6 16:21:04 unifi01 pkg[64878]: mongodb44-4.4.21 installed
That might be it. The upgrade might have caused this breakage.
mongo –shell
I found references saying get into the mongo shell
[12:02 unifi01 dan ~] % sudo mongo --shell
{"t":{"$date":"2023-05-11T12:03:20.212Z"},"s":"F", "c":"-", "id":23715, "ctx":"main","msg":"{str}","attr":{"str":"Failed to mlock: Cannot allocate locked memory. For more details see: https://dochub.mongodb.org/core/cannot-allocate-locked-memory: Operation not permitted"}}
{"t":{"$date":"2023-05-11T12:03:20.213Z"},"s":"F", "c":"-", "id":23089, "ctx":"main","msg":"Fatal assertion","attr":{"msgid":23715,"file":"src/mongo/base/secure_allocator.cpp","line":261}}
{"t":{"$date":"2023-05-11T12:03:20.213Z"},"s":"F", "c":"-", "id":23090, "ctx":"main","msg":"\n\n***aborting after fassert() failure\n\n"}
{"t":{"$date":"2023-05-11T12:03:20.213Z"},"s":"F", "c":"CONTROL", "id":4757800, "ctx":"main","msg":"Writing fatal message","attr":{"message":"Got signal: 6 (Abort trap).\n"}}
zsh: abort sudo mongo --shell
allow.mlock
The next search, found allow.mlock recommendations. So I added this to the configuration for that jail:
allow.mlock;
I restarted the jail, and tried the shell again:
[12:11 unifi01 dan ~] % mongo --shell MongoDB shell version v4.4.21 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:374:17 @(connect):2:6 __cxa_thread_call_dtors: dtr 0x803dae250 from unloaded dso, skipping exception: connect failed exiting with code 1
Oh look: https://www.freshports.org/net-mgmt/unifi7/#updating
These upgrade notes are taken from /usr/ports/UPDATING
2023-03-10
Affects: users of net-mgmt/unifi7
Author: otis@FreeBSD.org
Reason:
The mongodb dependency has been changed from 36 to 44, as MongoDB 3.6
is long out out support and end of life.
The upgrade path should be as following:
1. Take a backup from within the unifi7 application PRIOR to
updating!
2. Stop the unifi7 service (if running)
3. Copy the "backup" directory from LOCALBASE/share/java/unifi/data
to a safe location. Also copy keystore and system.properties if
you have made any modifications to those files
4. Remove files and directories under LOCALBASE/share/java/unifi/data
5. Upgrade the package
6. Copy the "backup" directory from a safe location back to
LOCALBASE/share/java/unifi/data
7. Start the service
8. Restore the configuration from backup
As an optional step, review system.properties and keystore to merge any
manual modifications you have made (this has to be done with the application
stopped)
Recovery
Here is an overview of the recovery process.
I followed the instructions in updating. NOTE: Step 4 is vital. Start from an empty data directory.
I copied the most recent backup down to my laptop.
I started the unifi service.
I did the restore process.
I waited. Eventually I noticed that unifi had stopped running. I had disabled the service earlier (service unifi disable) so I suspect that prevented the service from coming back up.
I started unifi manually. I saw messages in logs (sorry, no details) which led me to believe I needed to stop mongo manually and then start unifi.
I stopped unifi. I ran a kill -TERM on the mongo PID, then started unifi.
It took a few minutes but eventually the web page loaded, I logged in and everything was in there.
Thanks Nagios.
Edit: 2023-08-29 – When doing this same process, a few months later, at work, I found I did have to manually start unifi after the upgrade process. It seems that the restart (mentioned by the website after starting the restore) does not occur. I suggest waiting until you notice the java process no longer running, and then start unifi. This is java running after the upgrade:
[15:33 unifi01 dan ~] % ps auwwx | grep -i java unifi 82148 0.0 0.0 12816 1668 - IsJ Fri20 0:00.00 daemon: /usr/local/openjdk11/bin/java[82149] (daemon) unifi 82149 0.0 0.3 4572880 1210300 - IJ Fri20 26:22.53 /usr/local/openjdk11/bin/java -Djava.awt.headless=true -Xmx1024M -jar lib/ace.jar start unifi 84521 0.0 0.1 2297812 575516 - IJ Fri20 19:10.24 bin/mongod --dbpath /usr/local/share/java/unifi/data/db --port 27117 --unixSocketPrefix /usr/local/share/java/unifi/run --logRotate reopen --logappend --logpath /usr/local/share/java/unifi/logs/mongod.log --pidfilepath /usr/local/share/java/unifi/run/mongod.pid --wiredTigerEngineConfigString=cache_size=256M --bind_ip 127.0.0.1 dan 38757 0.0 0.0 12812 2384 5 S+J 15:34 0:00.00 grep -i java
