Monitor your backups

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 {
    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 -> 
/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.


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":""}}
{"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":"","port":27117,"unixDomainSocket":{"pathPrefix":"/usr/local/share/java/unifi/run"}},"processManagement":{"pidFilePath":"/usr/local/share/java/unifi/run/"},"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: 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


The next search, found allow.mlock recommendations. So I added this to the configuration for that jail:


I restarted the jail, and tried the shell again:

[12:11 unifi01 dan ~] % mongo --shell
MongoDB shell version v4.4.21
connecting to: mongodb://
Error: couldn't connect to server, connection attempt failed: SocketException: Error connecting to :: caused by :: Connection refused :
__cxa_thread_call_dtors: dtr 0x803dae250 from unloaded dso, skipping
exception: connect failed
exiting with code 1

Oh look:

These upgrade notes are taken from /usr/ports/UPDATING
Affects: users of net-mgmt/unifi7
  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

  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 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

  7. Start the service

  8. Restore the configuration from backup

  As an optional step, review and keystore to merge any
  manual modifications you have made (this has to be done with the application


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/ --wiredTigerEngineConfigString=cache_size=256M --bind_ip
dan    38757  0.0  0.0   12812    2384  5  S+J  15:34    0:00.00 grep -i java
Website Pin Facebook Twitter Myspace Friendfeed Technorati Digg Google StumbleUpon Premium Responsive

Leave a Comment

Scroll to Top