Additional debugging

juliuskoskela · juliuskoskela · commit 72f8543524d3 · 2026-03-20T06:20:46.000+02:00
Signed-off-by: Julius Koskela &lt;julius.koskela@unikie.com&gt;
Signed-off-by: Julius Koskela (Digimuoto Oy) &lt;julius.koskela@digimuoto.com&gt;
diff --git a/modules/common/logging/common.nix b/modules/common/logging/common.nix
@@ -70,7 +70,12 @@ let
 
       systemd-tmpfiles --create --prefix /var/log/journal
       systemctl restart systemd-journald.service
-      systemctl restart alloy.service
+
+      if systemctl cat alloy.service >/dev/null 2>&1; then
+        systemctl restart alloy.service
+      else
+        echo "alloy.service not installed, skipping restart"
+      fi
     '';
   };
 in
@@ -144,7 +149,9 @@ in
     };
 
     recovery = {
-      enable = mkEnableOption "journald/alloy recovery after realtime clock jumps";
+      enable = (mkEnableOption "journald/alloy recovery after realtime clock jumps") // {
+        default = true;
+      };
 
       thresholdSeconds = mkOption {
         description = "Only act on clock jumps >= this many seconds.";
diff --git a/modules/common/logging/fss-verify-classifier.sh b/modules/common/logging/fss-verify-classifier.sh
@@ -2,7 +2,7 @@
 # SPDX-FileCopyrightText: 2022-2026 TII (SSRC) and the Ghaf contributors
 # SPDX-License-Identifier: Apache-2.0
 # shellcheck shell=bash
-# shellcheck disable=SC2034
+# shellcheck disable=SC2034,SC2329
 
 # Shared helpers for classifying `journalctl --verify` output.
 
@@ -77,6 +77,67 @@ fss_append_line() {
   fi
 }
 
+# shellcheck disable=SC2329
+fss_count_nonempty_lines() {
+  local text="$1"
+  local line
+  local count=0
+
+  while IFS= read -r line || [ -n "$line" ]; do
+    if [ -n "$line" ]; then
+      count=$((count + 1))
+    fi
+  done <<<"$text"
+
+  printf '%s' "$count"
+}
+
+# shellcheck disable=SC2329
+fss_failure_bucket_for_path() {
+  local failure_path="$1"
+
+  case "$failure_path" in
+  *.journal~)
+    printf '%s' "temp"
+    ;;
+  */system.journal)
+    printf '%s' "active-system"
+    ;;
+  */system@*.journal)
+    printf '%s' "archived-system"
+    ;;
+  */user-[0-9]*.journal)
+    printf '%s' "user-journal"
+    ;;
+  *)
+    printf '%s' "other"
+    ;;
+  esac
+}
+
+# shellcheck disable=SC2329
+fss_unique_fail_paths_from_output() {
+  local output="$1"
+  local line
+  local failure_path
+  local unique_paths=""
+
+  while IFS= read -r line || [ -n "$line" ]; do
+    case "$line" in
+    FAIL:\ *)
+      failure_path="${line#FAIL: }"
+      failure_path="${failure_path%% *}"
+
+      if [ -n "$failure_path" ] && ! printf '%s\n' "$unique_paths" | grep -Fxq "$failure_path"; then
+        unique_paths=$(fss_append_line "$unique_paths" "$failure_path")
+      fi
+      ;;
+    esac
+  done <<<"$output"
+
+  printf '%s' "$unique_paths"
+}
+
 fss_reset_classification() {
   FSS_REASON_TAGS=""
   FSS_FAIL_LINES=""
diff --git a/tests/logging/test_scripts/fss-test.nix b/tests/logging/test_scripts/fss-test.nix
@@ -62,6 +62,161 @@ writeShellApplication {
         fail() { fss_log_fail "$1"; FAILED=$((FAILED + 1)); }
         warn() { fss_log_warn "$1"; WARNED=$((WARNED + 1)); }
         info() { fss_log_info "$1"; }
+        count_matches() {
+          local pattern="$1"
+          local text="$2"
+
+          printf '%s\n' "$text" | grep -Eic "$pattern" || true
+        }
+        print_prefixed_lines() {
+          local prefix="$1"
+          local text="$2"
+          local limit="''${3:-0}"
+          local line
+          local total=0
+          local shown=0
+
+          total=$(fss_count_nonempty_lines "$text")
+          if [ "$total" -eq 0 ]; then
+            return 0
+          fi
+
+          while IFS= read -r line || [ -n "$line" ]; do
+            if [ -z "$line" ]; then
+              continue
+            fi
+
+            shown=$((shown + 1))
+            if [ "$limit" -gt 0 ] && [ "$shown" -gt "$limit" ]; then
+              break
+            fi
+
+            printf '%s%s\n' "$prefix" "$line"
+          done <<<"$text"
+
+          if [ "$limit" -gt 0 ] && [ "$total" -gt "$limit" ]; then
+            printf '%s... (%s more lines)\n' "$prefix" "$((total - limit))"
+          fi
+        }
+        summarize_header_output() {
+          local header_output="$1"
+
+          printf '%s\n' "$header_output" | grep -E '^(State:|Compatible flags:|Incompatible flags:|Boot ID:|Machine ID:|Head realtime timestamp:|Tail realtime timestamp:|Tail monotonic timestamp:|Rotate suggested:|Disk usage:)' || true
+        }
+        summarize_file_verify_output() {
+          local verify_output="$1"
+
+          printf '%s\n' "$verify_output" | grep -E '(^[[:xdigit:]]+: )|(^File corruption detected)|(^FAIL: )|(^PASS: )|(^=> Validated)|(^Journal file .* is truncated, ignoring file\.)|(Required key not available)|(parse.*seed)|(tag/entry realtime timestamp out of synchronization)' || true
+        }
+        print_recent_journald_alerts() {
+          local alerts
+
+          alerts=$(journalctl -u systemd-journald --no-pager 2>/dev/null | grep -Ei 'corrupt|unclean|renaming and replacing|failed to append tag when closing journal|time jumped backwards|rotating|recover' | tail -n 12 || true)
+          if [ -n "$alerts" ]; then
+            echo "   Recent systemd-journald alerts:"
+            print_prefixed_lines "     " "$alerts"
+          fi
+        }
+        print_failed_file_diagnostics() {
+          local verify_output="$1"
+          local verify_key="$2"
+          local failed_paths
+          local failed_count=0
+          local path
+          local bucket
+          local stat_output
+          local header_output
+          local header_summary
+          local file_verify_output
+          local file_verify_summary
+          local path_limit=4
+          local total_failed_paths
+
+          failed_paths=$(fss_unique_fail_paths_from_output "$verify_output")
+          if [ -z "$failed_paths" ]; then
+            return 0
+          fi
+          total_failed_paths=$(fss_count_nonempty_lines "$failed_paths")
+
+          echo "   Detailed file diagnostics (up to $path_limit unique failing files):"
+          while IFS= read -r path || [ -n "$path" ]; do
+            if [ -z "$path" ]; then
+              continue
+            fi
+
+            failed_count=$((failed_count + 1))
+            if [ "$failed_count" -gt "$path_limit" ]; then
+              printf '     ... %s additional failing file(s) omitted\n' "$((total_failed_paths - path_limit))"
+              break
+            fi
+
+            bucket=$(fss_failure_bucket_for_path "$path")
+            printf '   - %s [%s]\n' "$path" "$bucket"
+
+            if [ ! -e "$path" ]; then
+              echo "     file no longer exists"
+              continue
+            fi
+
+            stat_output=$(stat -c 'size=%s mode=%a uid=%u gid=%g mtime=%y' "$path" 2>/dev/null || true)
+            if [ -n "$stat_output" ]; then
+              echo "     stat: $stat_output"
+            fi
+
+            header_output=$(journalctl --header --file="$path" 2>/dev/null || true)
+            header_summary=$(summarize_header_output "$header_output")
+            if [ -n "$header_summary" ]; then
+              print_prefixed_lines "     header: " "$header_summary" 8
+            fi
+
+            if [ -n "$verify_key" ]; then
+              file_verify_output=$(journalctl --verify --verify-key="$verify_key" --file="$path" 2>&1 || true)
+              file_verify_summary=$(summarize_file_verify_output "$file_verify_output")
+              if [ -n "$file_verify_summary" ]; then
+                print_prefixed_lines "     verify: " "$file_verify_summary" 8
+              fi
+            fi
+          done <<<"$failed_paths"
+        }
+        print_verify_diagnostics() {
+          local verify_output="$1"
+          local verify_tags="$2"
+          local verify_exit="$3"
+          local verify_key="''${4:-}"
+          local active_count
+          local archived_count
+          local user_count
+          local temp_count
+          local other_count
+          local tag_failed_count
+          local epoch_count
+          local time_sync_count
+          local corruption_count
+          local io_error_count
+          local fail_path_count
+
+          active_count=$(fss_count_nonempty_lines "$FSS_ACTIVE_SYSTEM_FAILURES")
+          archived_count=$(fss_count_nonempty_lines "$FSS_ARCHIVED_SYSTEM_FAILURES")
+          user_count=$(fss_count_nonempty_lines "$FSS_USER_FAILURES")
+          temp_count=$(fss_count_nonempty_lines "$FSS_TEMP_FAILURES")
+          other_count=$(fss_count_nonempty_lines "$FSS_OTHER_FAILURES")
+          fail_path_count=$(fss_count_nonempty_lines "$(fss_unique_fail_paths_from_output "$verify_output")")
+
+          tag_failed_count=$(count_matches 'Tag failed verification' "$verify_output")
+          epoch_count=$(count_matches 'Epoch sequence not continuous' "$verify_output")
+          time_sync_count=$(count_matches 'tag/entry realtime timestamp out of synchronization' "$verify_output")
+          corruption_count=$(count_matches 'File corruption detected at ' "$verify_output")
+          io_error_count=$(count_matches 'Input/output error|I/O error' "$verify_output")
+
+          printf '   Diagnostic summary: exit=%s tags=[%s] failing_files=%s active=%s archived=%s user=%s temp=%s other=%s\n' \
+            "$verify_exit" "$verify_tags" "$fail_path_count" "$active_count" "$archived_count" "$user_count" "$temp_count" "$other_count"
+          printf '   Signals: tag_failed=%s epoch_discontinuity=%s time_sync=%s file_corruption=%s io_error=%s key_parse=%s key_missing=%s filesystem_restriction=%s\n' \
+            "$tag_failed_count" "$epoch_count" "$time_sync_count" "$corruption_count" "$io_error_count" \
+            "$FSS_KEY_PARSE_ERROR" "$FSS_KEY_REQUIRED_ERROR" "$FSS_FILESYSTEM_RESTRICTION"
+
+          print_failed_file_diagnostics "$verify_output" "$verify_key"
+          print_recent_journald_alerts
+        }
 
         fss_log_block <<'EOF'
     ==========================================
@@ -209,26 +364,33 @@ writeShellApplication {
           if [ "$FSS_KEY_PARSE_ERROR" -eq 1 ] || [ "$FSS_KEY_REQUIRED_ERROR" -eq 1 ]; then
             fail "Journal verification failed due to verification key defect [$VERIFY_TAGS]"
             echo "   Output: $VERIFY_OUTPUT"
+            print_verify_diagnostics "$VERIFY_OUTPUT" "$VERIFY_TAGS" "$VERIFY_EXIT"
           elif [ -n "$FSS_ACTIVE_SYSTEM_FAILURES" ]; then
             fail "Active system journal verification failed [$VERIFY_TAGS]"
             echo "   Output: $VERIFY_OUTPUT"
+            print_verify_diagnostics "$VERIFY_OUTPUT" "$VERIFY_TAGS" "$VERIFY_EXIT" "$VERIFY_KEY"
           elif [ -n "$FSS_OTHER_FAILURES" ]; then
             fail "Journal verification found unclassified critical failures [$VERIFY_TAGS]"
             echo "   Output: $VERIFY_OUTPUT"
+            print_verify_diagnostics "$VERIFY_OUTPUT" "$VERIFY_TAGS" "$VERIFY_EXIT" "$VERIFY_KEY"
           elif [ -n "$FSS_ARCHIVED_SYSTEM_FAILURES" ] || [ -n "$FSS_USER_FAILURES" ]; then
             warn "Journal verification passed with archive/user warnings [$VERIFY_TAGS]"
             echo "   Output: $VERIFY_OUTPUT"
+            print_verify_diagnostics "$VERIFY_OUTPUT" "$VERIFY_TAGS" "$VERIFY_EXIT" "$VERIFY_KEY"
           elif [ -n "$FSS_TEMP_FAILURES" ]; then
             pass "Journal verification passed (temporary journal files ignored)"
             echo "   Ignored temp failures: $FSS_TEMP_FAILURES"
+            print_verify_diagnostics "$VERIFY_OUTPUT" "$VERIFY_TAGS" "$VERIFY_EXIT" "$VERIFY_KEY"
           elif [ "$VERIFY_EXIT" -eq 0 ]; then
             pass "Journal verification passed"
           elif [ "$FSS_FILESYSTEM_RESTRICTION" -eq 1 ]; then
             warn "Verification encountered filesystem restrictions [$VERIFY_TAGS]"
             echo "   Output: $VERIFY_OUTPUT"
+            print_verify_diagnostics "$VERIFY_OUTPUT" "$VERIFY_TAGS" "$VERIFY_EXIT"
           else
             warn "Verification returned exit code $VERIFY_EXIT without critical failures [$VERIFY_TAGS]"
             echo "   Output: $VERIFY_OUTPUT"
+            print_verify_diagnostics "$VERIFY_OUTPUT" "$VERIFY_TAGS" "$VERIFY_EXIT" "$VERIFY_KEY"
           fi
         fi
 
diff --git a/tests/logging/test_scripts/fss_verification.nix b/tests/logging/test_scripts/fss_verification.nix
@@ -126,6 +126,22 @@ _: ''
           [ -n "$FSS_OTHER_FAILURES" ]
           [ -z "$FSS_TEMP_FAILURES" ]
 
+          mixed_sample=$(printf "%s\n" \
+            "FAIL: /var/log/journal/mid/system.journal (Bad message)" \
+            "FAIL: /var/log/journal/mid/system.journal (Bad message)" \
+            "FAIL: /var/log/journal/mid/system@0000000000000001-0000000000000002.journal (Bad message)" \
+            "FAIL: /var/log/journal/mid/user-1000@0000000000000001-0000000000000002.journal (Bad message)" \
+            "FAIL: /var/log/journal/mid/system@0000000000000001-0000000000000002.journal~ (Bad message)" \
+            "FAIL: /var/log/journal/mid/custom.journal (Bad message)")
+          unique_fail_paths=$(fss_unique_fail_paths_from_output "$mixed_sample")
+          [ "$(fss_count_nonempty_lines "$unique_fail_paths")" -eq 5 ]
+          [ "$(printf "%s\n" "$unique_fail_paths" | grep -c '^/var/log/journal/mid/system.journal$')" -eq 1 ]
+          [ "$(fss_failure_bucket_for_path "/var/log/journal/mid/system.journal")" = "active-system" ]
+          [ "$(fss_failure_bucket_for_path "/var/log/journal/mid/system@0000000000000001-0000000000000002.journal")" = "archived-system" ]
+          [ "$(fss_failure_bucket_for_path "/var/log/journal/mid/user-1000@0000000000000001-0000000000000002.journal")" = "user-journal" ]
+          [ "$(fss_failure_bucket_for_path "/var/log/journal/mid/system@0000000000000001-0000000000000002.journal~")" = "temp" ]
+          [ "$(fss_failure_bucket_for_path "/var/log/journal/mid/custom.journal")" = "other" ]
+
           key_sample=$(printf "%s\n" \
             "Failed to parse seed." \
             "FAIL: /var/log/journal/mid/system.journal (Required key not available)")
@@ -167,6 +183,24 @@ _: ''
         '
       """)
 
+  with subtest("Clock-jump recovery defaults are enabled"):
+      machine.succeed("systemctl list-unit-files ghaf-clock-jump-watcher.service")
+      machine.succeed("systemctl list-unit-files ghaf-journal-alloy-recover.service")
+      machine.wait_for_unit("ghaf-clock-jump-watcher.service")
+      watcher_status = machine.succeed("systemctl show ghaf-clock-jump-watcher.service --property=ActiveState,UnitFileState")
+      if "ActiveState=active" not in watcher_status or "UnitFileState=enabled" not in watcher_status:
+          raise Exception(f"Clock-jump watcher not enabled by default: {watcher_status}")
+      print(f"Clock-jump recovery watcher status: {watcher_status}")
+
+  with subtest("Clock-jump recovery tolerates missing alloy service"):
+      exit_code, output = machine.execute("systemctl start ghaf-journal-alloy-recover.service 2>&1")
+      if exit_code != 0:
+          raise Exception(f"Clock-jump recovery service failed without alloy: {output}")
+      recover_status = machine.succeed("systemctl show ghaf-journal-alloy-recover.service --property=Result,ExecMainStatus")
+      if "Result=success" not in recover_status:
+          raise Exception(f"Clock-jump recovery service did not complete successfully: {recover_status}")
+      print(f"Clock-jump recovery service completed successfully: {recover_status}")
+
   with subtest("Journal files are created"):
       mid = machine.succeed("cat /etc/machine-id").strip()
       exit_code, journal_files = machine.execute(f"ls /var/log/journal/{mid}/*.journal 2>/dev/null || ls /run/log/journal/{mid}/*.journal 2>/dev/null")
