FreedomBox Shutting Down after less than an hour

Frankie · December 21, 2022, 12:41am

Currently on FB 22.27 running on top of Debian 11 (custom built PC). Shortly after 22.27 update the PC started shutting off. I don’t know if this problem is related to the update of course.

The box will power on and the FB server functions normally for about 30 to 60 minutes, I can use the services, etc., but then it will power off by itself.

Initially I thought there was a problem with the PC. Maybe a PSU or power related issue, etc. I checked the physical server, and ran some hardware diagnostics. PC kept running for 3+ hours with no problems found. I have another PC running on the same power strip and that one is fine.

After the hardware testing I booted up the FB again on the device just after 1PM local time and at around 2PM the box shut down by itself again. At this point I suspected the OS and grabbed the logs, which are attached.

In the logs it appears there is something going on with snapshots? Could this be why the server is shutting down? I tried restoring the FB to a backup from last week, however that did not solve the problem.

Here are the logs:

Blockquote

Status Log

These are the last 100 lines of the status log for this web interface. If you want to report a bug, please use the bug tracker and attach this status log to the bug report.

Caution: Please remove any passwords or other personal information from the log before submitting the bug report.

– Journal begins at Thu 2022-07-21 19:34:40 MST, ends at Wed 2022-12-21 14:01:13 MST. –
Dec 21 13:13:45 freedombox systemd[1]: Started FreedomBox Service (Plinth).
Dec 21 13:13:47 freedombox /usr/bin/plinth[670]: AXES: BEGIN LOG
Dec 21 13:13:47 freedombox /usr/bin/plinth[670]: AXES: Using django-axes version 5.4.3
Dec 21 13:13:47 freedombox /usr/bin/plinth[670]: AXES: blocking by IP only.
Dec 21 13:13:47 freedombox /usr/bin/plinth[670]: FreedomBox Service (Plinth) version - 22.26
Dec 21 13:13:47 freedombox /usr/bin/plinth[670]: Script prefix - /plinth
Dec 21 13:13:47 freedombox /usr/bin/plinth[670]: Initialized apps - apache, cockpit, names, avahi, diagnostics, help, snapshot, networks, firewall, config, storage, backups, ssh, power, letsencrypt, security, privacy, first_boot, sso, api, datetime, dynamicdns, users, upgrades, calibre, deluge, shaarli, infinoted, privoxy, transmission, zoph, minetest, pagekite, mumble, wordpress, performance, syncthing, mediawiki, samba, email, quassel, shadowsocks, searx, coturn, rssbridge, openvpn, gitweb, ttrss, minidlna, ejabberd, tor, i2p, roundcube, sharing, bind, matrixsynapse, ikiwiki, radicale, jsxc, bepasty, wireguard, janus
Dec 21 13:13:47 freedombox /usr/bin/plinth[670]: Added domain freedombox.local of type domain-type-local with services all
Dec 21 13:13:47 freedombox /usr/bin/plinth[670]: Added domain domain.sds-ip.de of type domain-type-static with services all
Dec 21 13:13:47 freedombox /usr/bin/plinth[670]: Added domain domain.sds-ip.de of type domain-type-dynamic with services all
Dec 21 13:13:47 freedombox /usr/bin/plinth[670]: # letsencrypt…get_status(…)
Dec 21 13:13:47 freedombox sudo[907]: plinth : PWD=/ ; USER=root ; COMMAND=/usr/share/plinth/actions/actions letsencrypt get_status --write-fd 7
Dec 21 13:13:47 freedombox sudo[907]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=124)
Dec 21 13:13:49 freedombox sudo[907]: pam_unix(sudo:session): session closed for user root
Dec 21 13:13:49 freedombox /usr/bin/plinth[670]: # ikiwiki…get_sites(…)
Dec 21 13:13:49 freedombox sudo[994]: plinth : PWD=/ ; USER=root ; COMMAND=/usr/share/plinth/actions/actions ikiwiki get_sites --write-fd 7
Dec 21 13:13:49 freedombox sudo[994]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=124)
Dec 21 13:13:49 freedombox sudo[994]: pam_unix(sudo:session): session closed for user root
Dec 21 13:13:49 freedombox /usr/bin/plinth[670]: Checking if any Let’s Encrypt certificates got renewed.
Dec 21 13:13:49 freedombox /usr/bin/plinth[670]: # letsencrypt…get_status(…)
Dec 21 13:13:49 freedombox sudo[999]: plinth : PWD=/ ; USER=root ; COMMAND=/usr/share/plinth/actions/actions letsencrypt get_status --write-fd 7
Dec 21 13:13:49 freedombox sudo[999]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=124)
Dec 21 13:13:50 freedombox sudo[999]: pam_unix(sudo:session): session closed for user root
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: Certificate for domain.sds-ip.de is already the latest known.
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: Running regular setup.
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: Started new thread for glib main loop.
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: Setting up CherryPy server
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: Creating network manager client
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: D-Bus connection acquired: org.freedombox.Service
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: D-Bus name acquired: org.freedombox.Service
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: Created Network manager client
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: Running setup for apps, essential - True, selected apps - None
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: Setup thread finished.
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: [21/Dec/2022:13:13:50] ENGINE Listening for SIGTERM.
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: [21/Dec/2022:13:13:50] ENGINE Listening for SIGHUP.
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: [21/Dec/2022:13:13:50] ENGINE Listening for SIGUSR1.
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: [21/Dec/2022:13:13:50] ENGINE Bus STARTING
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: [21/Dec/2022:13:13:50] ENGINE Started monitor thread ‘TimeoutMonitor’.
Dec 21 13:13:50 freedombox /usr/bin/plinth[670]: Drive PNY-CS900-120GB-SSD-PNY4220229520010DDD6 appears healthy
Dec 21 13:13:51 freedombox /usr/bin/plinth[670]: [21/Dec/2022:13:13:51] ENGINE Serving on http://127.0.0.1:8000
Dec 21 13:13:51 freedombox /usr/bin/plinth[670]: [21/Dec/2022:13:13:51] ENGINE Bus STARTED
Dec 21 13:13:51 freedombox /usr/bin/plinth[670]: New filesystem found: by-id-ata-PNY_CS900_120GB_SSD_PNY4220229520010DDD6-part1 /dev/sda1
Dec 21 13:13:51 freedombox /usr/bin/plinth[670]: Ignoring auto-mount on already mounted device: by-id-ata-PNY_CS900_120GB_SSD_PNY4220229520010DDD6-part1 /dev/sda1
Dec 21 13:18:32 freedombox /usr/bin/plinth[670]: Apt package cache updated.
Dec 21 13:18:32 freedombox /usr/bin/plinth[670]: Waiting for 1800 seconds before attempting upgrade
Dec 21 13:18:50 freedombox /usr/bin/plinth[670]: Updating dynamic domain domain.sds-ip.de, DNS address ip-hidden, looked up external address None
Dec 21 13:19:31 freedombox /usr/bin/plinth[670]: Apt package cache updated.
Dec 21 13:19:31 freedombox /usr/bin/plinth[670]: Package upgrade already in process
Dec 21 13:23:50 freedombox /usr/bin/plinth[670]: Updating dynamic domain domain.sds-ip.de, DNS address ip-hidden, looked up external address None
Dec 21 13:24:34 freedombox /usr/bin/plinth[670]: # upgrades…check_auto(…)
Dec 21 13:24:34 freedombox sudo[4786]: plinth : PWD=/ ; USER=root ; COMMAND=/usr/share/plinth/actions/actions upgrades check_auto --write-fd 16
Dec 21 13:24:34 freedombox sudo[4786]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=124)
Dec 21 13:24:34 freedombox sudo[4786]: pam_unix(sudo:session): session closed for user root
Dec 21 13:24:34 freedombox /usr/bin/plinth[670]: # plinth…is_package_manager_busy(…)
Dec 21 13:24:34 freedombox sudo[4796]: plinth : PWD=/ ; USER=root ; COMMAND=/usr/share/plinth/actions/actions plinth is_package_manager_busy --write-fd 16
Dec 21 13:24:34 freedombox sudo[4796]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=124)
Dec 21 13:24:34 freedombox sudo[4796]: pam_unix(sudo:session): session closed for user root
Dec 21 13:24:34 freedombox /usr/bin/plinth[670]: # upgrades…get_log(…)
Dec 21 13:24:34 freedombox sudo[4802]: plinth : PWD=/ ; USER=root ; COMMAND=/usr/share/plinth/actions/actions upgrades get_log --write-fd 16
Dec 21 13:24:34 freedombox sudo[4802]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=124)
Dec 21 13:24:35 freedombox sudo[4802]: pam_unix(sudo:session): session closed for user root
Dec 21 13:24:39 freedombox /usr/bin/plinth[670]: # users…get_user_groups(…)
Dec 21 13:24:39 freedombox sudo[4810]: plinth : PWD=/ ; USER=root ; COMMAND=/usr/share/plinth/actions/actions users get_user_groups --write-fd 18
Dec 21 13:24:39 freedombox sudo[4810]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=124)
Dec 21 13:24:39 freedombox ldapsearch[4853]: DIGEST-MD5 common mech free
Dec 21 13:24:39 freedombox ldapsearch[4859]: DIGEST-MD5 common mech free
Dec 21 13:24:39 freedombox ldapsearch[4868]: DIGEST-MD5 common mech free
Dec 21 13:24:39 freedombox ldapsearch[4878]: DIGEST-MD5 common mech free
Dec 21 13:24:39 freedombox ldapsearch[4894]: DIGEST-MD5 common mech free
Dec 21 13:24:39 freedombox sudo[4810]: pam_unix(sudo:session): session closed for user root
Dec 21 13:28:49 freedombox /usr/bin/plinth[670]: Updating dynamic domain domain.sds-ip.de, DNS address ip-hidden, looked up external address None
Dec 21 13:33:50 freedombox /usr/bin/plinth[670]: Updating dynamic domain domain.sds-ip.de, DNS address ip-hidden, looked up external address None
Dec 21 13:38:49 freedombox /usr/bin/plinth[670]: Updating dynamic domain domain.sds-ip.de, DNS address ip-hidden, looked up external address None
Dec 21 13:57:34 freedombox /usr/bin/plinth[670]: Attempting to perform upgrade
Dec 21 13:57:34 freedombox /usr/bin/plinth[670]: # plinth…is_package_manager_busy(…)
Dec 21 13:57:34 freedombox sudo[7207]: plinth : PWD=/ ; USER=root ; COMMAND=/usr/share/plinth/actions/actions plinth is_package_manager_busy --write-fd 14
Dec 21 13:57:34 freedombox sudo[7207]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=124)
Dec 21 13:57:34 freedombox sudo[7207]: pam_unix(sudo:session): session closed for user root
Dec 21 13:57:35 freedombox /usr/bin/plinth[670]: Apps needing conffile upgrades: None
Dec 21 14:00:55 freedombox /usr/bin/plinth[670]: # snapshot…get_config(…)
Dec 21 14:00:55 freedombox sudo[7993]: plinth : PWD=/ ; USER=root ; COMMAND=/usr/share/plinth/actions/actions snapshot get_config --write-fd 17
Dec 21 14:00:55 freedombox sudo[7993]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=124)
Dec 21 14:00:55 freedombox /usr/share/plinth/actions/actions[7996]: Error executing action: Command ‘[‘snapper’, ‘get-config’]’ returned non-zero exit status 1.
Traceback (most recent call last):
File “/usr/share/plinth/actions/actions”, line 92, in call
return_values = func(arguments[‘args’], **arguments[‘kwargs’])
File “/usr/lib/python3/dist-packages/plinth/modules/snapshot/privileged.py”, line 225, in get_config
return _get_config()
File “/usr/lib/python3/dist-packages/plinth/modules/snapshot/privileged.py”, line 213, in _get_config
process = subprocess.run(command, stdout=subprocess.PIPE, check=True)
File “/usr/lib/python3.9/subprocess.py”, line 528, in run
raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command ‘[‘snapper’, ‘get-config’]’ returned non-zero exit status 1.
Dec 21 14:00:56 freedombox sudo[7993]: pam_unix(sudo:session): session closed for user root
Dec 21 14:00:56 freedombox /usr/bin/plinth[670]: Error running action snapshot…get_config((), **{}): Command ‘[‘snapper’, ‘get-config’]’ returned non-zero exit status 1. (1, [‘snapper’, ‘get-config’], b’', b’The config 'root' does not exist. Likely snapper is not configured.\nSee 'man snapper' for further instructions.\n\x1b[31m ERROR\x1b[0m \x1b[94m__main \x1b[0m Error executing action: Command '['snapper', 'get-config']' returned non-zero exit status 1.\nTraceback (most recent call last):\n File “/usr/share/plinth/actions/actions”, line 92, in _call\n return_values = func(*arguments['args'], **arguments['kwargs'])\n File “/usr/lib/python3/dist-packages/plinth/modules/snapshot/privileged.py”, line 225, in get_config\n return _get_config()\n File “/usr/lib/python3/dist-packages/plinth/modules/snapshot/privileged.py”, line 213, in _get_config\n process = subprocess.run(command, stdout=subprocess.PIPE, check=True)\n File “/usr/lib/python3.9/subprocess.py”, line 528, in run\n raise CalledProcessError(retcode, process.args,\nsubprocess.CalledProcessError: Command '['snapper', 'get-config']' returned non-zero exit status 1.\n’) [’ File “/usr/share/plinth/actions/actions”, line 92, in _call\n return_values = func(*arguments['args'], **arguments['kwargs'])\n’, ’ File “/usr/lib/python3/dist-packages/plinth/modules/snapshot/privileged.py”, line 225, in get_config\n return _get_config()\n’, ’ File “/usr/lib/python3/dist-packages/plinth/modules/snapshot/privileged.py”, line 213, in _get_config\n process = subprocess.run(command, stdout=subprocess.PIPE, check=True)\n’, ’ File “/usr/lib/python3.9/subprocess.py”, line 528, in run\n raise CalledProcessError(retcode, process.args,\n’]
Dec 21 14:00:56 freedombox /usr/bin/plinth[670]: Internal Server Error: /plinth/sys/snapshot/
Traceback (most recent call last):
File “/usr/lib/python3/dist-packages/django/core/handlers/exception.py”, line 34, in inner
response = get_response(request)
File “/usr/lib/python3/dist-packages/django/core/handlers/base.py”, line 115, in _get_response
response = self.process_exception_by_middleware(e, request)
File “/usr/lib/python3/dist-packages/django/core/handlers/base.py”, line 113, in _get_response
response = wrapped_callback(request, *callback_args, **callback_kwargs)
File “/usr/lib/python3/dist-packages/django/views/generic/base.py”, line 71, in view
return self.dispatch(request, *args, **kwargs)
File “/usr/lib/python3/dist-packages/django/views/generic/base.py”, line 97, in dispatch
return handler(request, *args, **kwargs)
File “/usr/lib/python3/dist-packages/django/views/generic/edit.py”, line 133, in get
return self.render_to_response(self.get_context_data())
File “/usr/lib/python3/dist-packages/plinth/modules/snapshot/views.py”, line 69, in get_context_data
context = super().get_context_data(*args, **kwargs)
File “/usr/lib/python3/dist-packages/plinth/views.py”, line 252, in get_context_data
context = super().get_context_data(*args, **kwargs)
File “/usr/lib/python3/dist-packages/django/views/generic/edit.py”, line 66, in get_context_data
kwargs[‘form’] = self.get_form()
File “/usr/lib/python3/dist-packages/plinth/views.py”, line 197, in get_form
return super().get_form(*args, **kwargs)
File “/usr/lib/python3/dist-packages/django/views/generic/edit.py”, line 33, in get_form
return form_class(**self.get_form_kwargs())
File “/usr/lib/python3/dist-packages/django/views/generic/edit.py”, line 38, in get_form_kwargs
‘initial’: self.get_initial(),
File “/usr/lib/python3/dist-packages/plinth/modules/snapshot/views.py”, line 64, in get_initial
initial.update(get_configuration())
File “/usr/lib/python3/dist-packages/plinth/modules/snapshot/init.py”, line 113, in get_configuration
output = privileged.get_config()
File “/usr/lib/python3/dist-packages/plinth/actions.py”, line 57, in wrapper
return _run_privileged_method_as_process(module_name, action_name,
File “/usr/lib/python3/dist-packages/plinth/actions.py”, line 116, in _run_privileged_method_as_process
return _wait_for_return(*wait_args)
File “/usr/lib/python3/dist-packages/plinth/actions.py”, line 154, in _wait_for_return
raise exception
subprocess.CalledProcessError: Command ‘[‘snapper’, ‘get-config’]’ returned non-zero exit status 1.
Dec 21 14:01:13 freedombox /usr/bin/plinth[670]: # help…get_logs(…)
Dec 21 14:01:13 freedombox sudo[8000]: plinth : PWD=/ ; USER=root ; COMMAND=/usr/share/plinth/actions/actions help get_logs --write-fd 17
Dec 21 14:01:13 freedombox sudo[8000]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=124)

Blockquote

joseph · December 23, 2022, 8:54pm

If this is complaining about snapshots and causing a problem hourly I would be suspicious of interaction with timeline snapshots. I can’t address the power down, but perhaps if you check some snapshot basics this may at least improve.

FB filesystem snapshots app is intended for a btrfs root partition. Does that match your setup?
btrfs users should use single device, or raid0 or raid1. Raid5/6 are not ready for production.
disable hourly timeline snapshots
reduce your snapshot frequency in general - use the minimum setting you think you can get by with
remove snapshots you do not require. Too many snapshots can catch up to you and cause issues
you should scrub btrfs filesystem from time to time which can be automated using btrfstools.
btrfs raid0/raid1 can use a rebalance sometimes, also can be done using btrfstools

If you are using raid5/6 btrfs you may read the btrfs wiki to understand that situation and consider a layout change to raid0/1.

Frankie · December 23, 2022, 11:04pm

I very much appreciate the info, thank you.

It appears that Snapshots is not responding:

The log I posted is the ‘status log’ mentioned in the screen shot. Should I try to restart a service or something? Seems strange that it brings down the PC also, but that is what seems to be happening.

Frankie · December 23, 2022, 11:08pm

I have started the PC again, poking around and see this. System resource usage seems normal.

Look at this, snapshot seems to have a conflict with ‘shutdown.target’, which would explain why the PC shuts down. I wonder why? This is out of my depth. I really do need some help. Any logs I can grab?

jvalleroy · December 24, 2022, 4:36pm

Since you said “on top of Debian 11”, I think you installed Debian using the normal installer, and likely have an ext4 filesystem instead of btrfs. This means that Snapshots module has no effect on your system (ext4 does not support snapshots). The error displayed in Snapshots was fixed very recently (https://salsa.debian.org/freedombox-team/freedombox/-/issues/2268). After the update, you should see a message that snapshots are not supported.

Is it possible that you have a desktop environment such as Gnome/KDE/XFCE running in the background? I am wondering if some desktop power management is causing the device to shutdown.

Frankie · December 24, 2022, 11:10pm

Yes, it is a desktop environment. Gnome. I totally forgot about this, thought it was Debian server I had installed.

I think you are right about the power settings. I just logged into the box and turned off suspend on idle in the power settings. Thank You Very Much!

If it stays up longer than an hour then I know that is the reason.

Frankie · December 25, 2022, 3:40pm

To confirm @jvalleroy the problem is solved. Thank You! Hopefully this setting doesn’t change again. Is there a config file I can edit and lock so this never happens again?

jvalleroy · December 25, 2022, 4:54pm

If you don’t plan to use Gnome, you can uninstall it:

nbenedek · December 26, 2022, 2:46pm

@jvalleroy Do you think we can break the gnome-power-manager package like we did with ufw?

jvalleroy · December 29, 2022, 12:05am

No, I don’t think we should. I think documenting it is sufficient.

sunil · December 29, 2022, 7:25pm

I think FreedomBox service can request inhibition of “suspend” by making a DBus call to systemd. This is similar to how browsers, video players etc. prevent the machine from getting automatically suspended. If we do this, FreedomBox and Desktops can co-exist a bit better without stepping on each other.

KenW · January 15, 2024, 5:37am

Hi Frankie,
I think you have the solution I need. Any details you can provide on turning off suspend on idle would be welcome.
Thanks, KenW