systemcheck error/script bug

mimp · January 2, 2022, 2:07am

got this in a working gateway from running:

$systemcheck --verbose --leak-tests

partial output it said to report

failed:
########################################
[ERROR] [systemcheck] ###############################################################################
## systemcheck script bug.
## No panic. Nothing is broken. Just some rare condition has been hit.
## Try again later. There is likely a solution for this problem.
## Please see Whonix News, Whonix Blog and Whonix User Help Forum.
## Please report this bug!
##
## who_ami: systemcheck
## identifier: 
## IDENTIFIER: systemcheck
## exit_code: 0
## error_cause: error_handler signal ERR detected with BASH_COMMAND:
/usr/libexec/msgcollector/br_add "$grep_fail_output"
##
## Experts only:
## bash -x systemcheck --verbose
## for verbose output. Clean the output and report to Whonix developers.
#########################################################################
systemcheck: signal ERR received. Cleaning up... Exiting...
[INFO] [systemcheck] systemcheck aborted! (SIGNAL_TYPE: ERR)

Patrick · January 2, 2022, 9:29am

I see. Well, I didn’t really consider that box to imply “copy that box only”.

This is very weird. I don’t see how this could go unnoticed for years and now suddenly fail for 1 user.

Related source code:

github.com

Kicksecure/msgcollector/blob/master/usr/libexec/msgcollector/br_add

#!/usr/bin/python3 -u

## Copyright (C) 2014 troubadour <trobador@riseup.net>
## Copyright (C) 2014 - 2023 ENCRYPTED SUPPORT LP <adrelanos@whonix.org>
## See the file COPYING for copying conditions.

import sys
in_ = sys.argv[1]
out = '<br />\n'.join(in_.split('\n'))
print(out)

github.com

Kicksecure/systemcheck/blob/master/usr/libexec/systemcheck/check_services.bsh#L111


      
          local apparmorinfo_output journalctl_output grep_warn_output grep_error_output grep_ordering_output grep_seccomp_output
          
          setsid -- sudo --non-interactive -- /usr/sbin/apparmor-info --boot | tee "$TEMP_DIR/apparmor-info.txt" >/dev/null || true
          ## '--priority=0..4'
          ## "emerg" (0), "alert" (1), "crit" (2), "err" (3), "warning" (4)
          setsid -- sudo --non-interactive -- /bin/journalctl --boot --no-pager | tee "$TEMP_DIR/journalctl_output.txt" >/dev/null || true
          
          ## grep will exit 1 if no match, therefore overwrite with || true.
          cat "$TEMP_DIR/journalctl_output.txt" | grep -i "SECCOMP" | grep 'syscall=' | tee "$TEMP_DIR/journalctl_seccomp.txt" >/dev/null || true
          cat "$TEMP_DIR/journalctl_output.txt" | grep -i "warn" | tee "$TEMP_DIR/journalctl_warn.txt" >/dev/null || true
          cat "$TEMP_DIR/journalctl_output.txt" | grep -i "fail" | grep --invert-match "faillock" | tee "$TEMP_DIR/journalctl_fail.txt" >/dev/null || true
          cat "$TEMP_DIR/journalctl_output.txt" | grep -i "error" | tee "$TEMP_DIR/journalctl_error.txt" >/dev/null || true
          cat "$TEMP_DIR/journalctl_output.txt" | grep -i "ordering cycle" | tee "$TEMP_DIR/journalctl_orderingcycle.txt" >/dev/null || true
          
          ## Cannot use /usr/libexec/msgcollector/br_add due to 'getconf ARG_MAX' limit.
          br_add_to_file "$TEMP_DIR/apparmor-info.txt"
          br_add_to_file "$TEMP_DIR/journalctl_seccomp.txt"
          br_add_to_file "$TEMP_DIR/journalctl_warn.txt"
          br_add_to_file "$TEMP_DIR/journalctl_fail.txt"
          br_add_to_file "$TEMP_DIR/journalctl_error.txt"
          br_add_to_file "$TEMP_DIR/journalctl_orderingcycle.txt"

To gather more debug output, please run:

systemcheck --debug --verbose --function check_journal

mimp · January 2, 2022, 11:40pm

 systemcheck --debug --verbose --function check_journal | less

returns

systemcheck debug output...
Script running as systemcheck
[ESC[32mINFOESC(BESC[m] [systemcheck] systemd journal check Result:
warnings:
########################################

########################################

failed:
########################################
Jan 02 16:16:38 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:18:59 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:21:15 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:21:49 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:22:26 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:22:48 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:23:25 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:23:57 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:24:47 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:25:02 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:25:24 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:25:45 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:28:01 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:28:29 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:29:01 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:29:20 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:29:35 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:29:56 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:30:17 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:30:56 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:31:33 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:32:06 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:32:27 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
Jan 02 16:32:45 host systemd[1]: sdwdate.service: Failed with result 'exit-code'.
[repeats this over and over and over]

########################################

errors:
########################################
Jan 02 16:12:57 host kernel: ACPI Error: No handler or method for GPE 00, disabling event (20200925/evgpe-839)
Jan 02 16:12:57 host kernel: ACPI Error: No handler or method for GPE 01, disabling event (20200925/evgpe-839)
Jan 02 16:12:57 host kernel: ACPI Error: No handler or method for GPE 03, disabling event (20200925/evgpe-839)
Jan 02 16:12:57 host kernel: ACPI Error: No handler or method for GPE 04, disabling event (20200925/evgpe-839)
Jan 02 16:12:57 host kernel: ACPI Error: No handler or method for GPE 05, disabling event (20200925/evgpe-839)
Jan 02 16:12:57 host kernel: ACPI Error: No handler or method for GPE 06, disabling event (20200925/evgpe-839)
Jan 02 16:12:57 host kernel: ACPI Error: No handler or method for GPE 07, disabling event (20200925/evgpe-839)
Jan 02 16:15:01 host kernel: Error: Driver 'pcspkr' is already registered, aborting...
########################################

denied:
########################################

########################################

ordering cycle:
########################################

########################################

To see this for yourself...
1. Open a terminal. (dom0 -> Start Menu -> ServiceVM: [Qubename] -> Terminal)
2. Run. sudo journalctl --boot | grep -i warn
3. Run. sudo journalctl --boot | grep -i fail
4. Run. sudo journalctl --boot | grep -i error
5. Run. sudo journalctl --boot | grep -i denied
6. Run. sudo journalctl --boot | grep -i "ordering cycle"

If you know what you are doing, feel free to disable this check.
Create a file /etc/systemcheck.d/50_user.conf and add:
systemcheck_skip_functions+=" check_journal "

Patrick · January 3, 2022, 8:38am

Transient issue? Not happening anymore?

mimp · January 3, 2022, 4:13pm

Guess so. I did get it a couple times, but have rebooted since.

The sdwdate.service Failed messages seemed bad though.

systemcheck on the workstation gave:

[INFO] [systemcheck] libzone | Whonix-Workstation | Standalone AppVM | Mon 03 Jan 2022 04:23:35 PM UTC
[ERROR] [systemcheck] Time Synchronization Result:
systemcheck gave up waiting.

Time synchronization status: fail
sdwdate reports: General Timeout Error. Internet connection might be down.
whonix_firewall status: first run after boot

Possible issues:

- sdwdate time sources might be dysfunctional.

Recommendations:

A) Rerun systemcheck:
dom0 -> Start Menu -> Domain: libzone -> systemcheck
or in Terminal: systemcheck
or more verbose in Terminal: systemcheck --verbose --gui --cli

B) Restart sdwdate.
dom0 -> Start Menu -> Domain: libzone -> sdwdate-gui -> right click on sdwdate-gui systray -> Restart sdwdate
or in Terminal: sudo service sdwdate restart

C) Manually set the time.

As last resort...

1. Open a terminal. (dom0 -> Start Menu -> Domain: libzone -> Terminal)
2. Use the manual clock setting tool. sudo --set-home clock-random-manual-gui
3. Simulate sdwdate success. sudo -u sdwdate touch /run/sdwdate/first_success
4. Rerun systemcheck.

Gateway sdwdate status gives:

Last message from [gateway] sdwdate: Time fetching in progress...

Workstation sdwdate status:

 General Timeout Error: Internet connection might be down.

Internet connection is not down. I restarted sdwdate on gateway, got same messages. I restarted sdwdate on workstation, now it gives “Success” as status.

Seems OK.

Patrick · January 4, 2022, 7:38am

These are all very different issues happening randomly and non-reproducible. I would expect Hardware Issues.

Yet a different issue.