Skip to content

Feat/consistent job logging - #121

Merged
leontappe merged 14 commits into
masterfrom
feat/consistent-job-logging
Aug 6, 2026
Merged

Feat/consistent job logging#121
leontappe merged 14 commits into
masterfrom
feat/consistent-job-logging

Conversation

@leontappe

Copy link
Copy Markdown
Contributor

No description provided.

leontappe and others added 12 commits July 24, 2026 17:35
The logrus formatter of both binaries hardcoded the day-first layout
"02-01-2006 15:04:05", which is ambiguous and carries no timezone.

Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
enableTimestamps = true without an explicit timestampFormat fell into the
unknown-format branch and warned on every job start, even though RFC3339
is the documented default for exactly this case.

Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
NewBootJob constructed the embedded baseJob directly and never set
job.stdout/job.stderr. The typed-nil *os.File values bypass os/exec's
nil check (Fd() returns ^0), so the child started with closed
stdout/stderr descriptors: all boot job output went nowhere, and the
first file the boot command opened could silently receive fd 1.

Initializing via baseJob.init wires boot jobs to mittnite's own streams
and makes them honor the stdout/stderr/enableTimestamps job options,
like regular jobs.

Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
logWithTimestamp used bufio.Scanner, whose 64KB token limit turns an
overlong line into a permanent read error: forwarding stops, and the
deferred Close of the pipe's read end kills the job with SIGPIPE on its
next write. The forwarder (renamed to forwardOutput) now reads via
bufio.Reader.ReadLine and splits overlong lines across writes instead —
the timestamp is only written at the start of a line, the newline only
at its end.

Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
mittnite up learns --job-log-timestamps and --job-log-name-prefix (env:
MITTNITE_JOB_LOG_TIMESTAMPS / MITTNITE_JOB_LOG_NAME_PREFIX). They apply
to every job and boot job that does not configure the respective option
itself; enableTimestamps and the new enableNamePrefix are bool-pointers
now, so an explicit per-job false still opts out of the global default.

The name prefix is written after the timestamp — RFC3339 keeps a
constant width for a fixed UTC offset, so the name column stays aligned
and tooling that expects a leading timestamp keeps working:

    [2026-07-24T10:28:52Z] [php-fpm] NOTICE: fpm is running, pid 592

Fixes #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
closeStdFiles runs the moment startOnce returns, while the forwarder
goroutines are still draining the pipes; a job's own final output lines
could race into the ErrClosed discard path and be lost. startOnce now
waits for the forwarders to hit EOF before the files are closed. EOF
arrives as soon as the job's last write end is gone, so the wait is
normally instant. Only when forked children outlive the job does the
one-second cap strike: what they write within that window still reaches
the file; output after the close is discarded.

Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The forwarder goroutines read job.stdout/job.stderr inside their
closures since the flush wait was introduced. When that wait times out
because a lingering child keeps the pipes open, the forwarders outlive
startOnce, and the next start's CreateAndOpenStdFile reassigns both
fields without a happens-before edge to those reads. Capture the targets
before spawning, as the plain go statement did before.

Found by go test -race on a restart-under-lingering-children repro,
which is added as a regression test.

Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
- cover the MITTNITE_JOB_LOG_* environment switches (envBool,
  warnUnparsableEnvBools), which had no tests
- make the overlong-line test independent of the wall-clock year
- pin that ApplyJobLogDefaults materializes an explicit false, which is
  visible in the job status API
- the forwarder comment claimed a stopped reader would block the child
  on a full pipe; the deferred Close of the read end actually kills it
  with SIGPIPE on the next write

Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Opening the configured log files in NewBootJob (via baseJob.init) made
an unopenable path fail the construction: Runner.Boot returned before
any boot job ran and mittnite aborted fatally, where on master the same
config booted with a "job failed, but is allowed to fail" warning. The
constructor-opened files also leaked, since startOnce reopens them and
closeStdFiles only closes that second pair.

init no longer performs file I/O; startOnce opens the files on every
start, and the error flows through BootJob.Run's canFail handling again.
Common and lazy jobs keep failing fast on broken paths: their
constructors still open the files explicitly.

closeStdFiles now also refuses to close the process-wide streams: after
a failed open, job.stdout/job.stderr still point at os.Stdout/os.Stderr,
and closing those silenced all further forwarded output of every job.
Boot-job errors in Runner.Boot carry the job name now, like Runner.Init.

Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The flush wait only covered jobs with file-backed log targets. For
passthrough targets the forwarders race mittnite's own exit instead: a
boot job that dumps diagnostics and fails takes the whole process down
right after startOnce returns, truncating exactly the output that
explains the failure. The bounded wait is safe for passthrough targets
(they are never closed), so apply it to every decorated job.

Also assert the one-second cap in the restart-race test: an unbounded
wait would block startOnce on lingering children, making the job
unrestartable and shutdown hang.

Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Chunks of an overlong line are separate writes; on a target shared with
other forwarders, their output can interleave between the chunks.

Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

Copilot AI left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

This PR improves job log formatting consistency by introducing a line-based output forwarder that can prefix each job output line with timestamps and/or the job name, and by adding global defaults (CLI flags + env vars) that can be overridden per job (including explicit opt-outs). It also fixes boot-job logging initialization so boot job output is not silently lost, and improves boot job initialization error context.

Changes:

  • Add enableNamePrefix and global job-log defaults applied across jobs/boot jobs (--job-log-timestamps, --job-log-name-prefix, MITTNITE_JOB_LOG_TIMESTAMPS, MITTNITE_JOB_LOG_NAME_PREFIX).
  • Replace timestamp-only forwarding with a unified line forwarder that supports timestamps and/or job name, including safe handling of >64KiB lines.
  • Ensure boot jobs initialize stdout/stderr correctly and improve error wrapping during boot job initialization.

Reviewed changes

Copilot reviewed 13 out of 13 changed files in this pull request and generated 1 comment.

Show a summary per file
File Description
README.md Documents default timestamp format, name prefixing, global flags/env vars, and long-line chunking/interleaving behavior.
pkg/proc/types.go Changes base job initialization and job constructors; boot jobs now call base init; constructors validate log paths.
pkg/proc/runner.go Wraps boot-job initialization errors with the boot job name for better diagnostics.
pkg/proc/basejob.go Implements unified line forwarder (timestamp + name prefix), improves timestamp-format defaulting, and adjusts std file closing semantics.
pkg/proc/basejob_test.go Adds extensive coverage for boot-job stdout/stderr init, canFail behavior with unopenable log targets, timestamp defaulting, and forwarder behavior.
main.go Switches logrus formatter timestamp format to RFC3339.
internal/config/types.go Makes log toggles tri-state (*bool) and adds accessors for enabled checks.
internal/config/types_test.go Adds tests for tri-state HCL unmarshalling and global default materialization behavior.
internal/config/ignitionconfig.go Adds ApplyJobLogDefaults to materialize global log switches per job/boot job.
examples/timestamps.d/timestamps.hcl Adds an example job enabling both timestamps and name prefix.
cmd/up.go Adds global flags/env parsing + warnings for unparsable env values; applies job-log defaults after config load.
cmd/up_test.go Tests env-var boolean parsing and warning behavior.
cmd/mittnitectl/main.go Switches logrus formatter timestamp format to RFC3339.
Comments suppressed due to low confidence (1)

pkg/proc/types.go:202

  • NewLazyJob opens configured stdout/stderr log files in the constructor, but startOnce also opens them on every run. Since CreateAndOpenStdFile doesn't close previously opened handles before overwriting job.stdout/job.stderr, this constructor-time open leaks file descriptors. Close/reset after the validation open (or remove this open entirely) so only startOnce owns the per-run file handles.
	j.baseJob.init(&c.BaseJobConfig)

	if err := j.baseJob.CreateAndOpenStdFile(&c.BaseJobConfig); err != nil {
		return nil, err

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment thread pkg/proc/types.go Outdated
leontappe and others added 2 commits July 31, 2026 13:33
NewCommonJob and NewLazyJob opened the configured log files for early
validation, but startOnce opens its own handles on every run and
CreateAndOpenStdFile overwrites job.stdout/job.stderr without closing
the previous pair — the constructor-opened descriptors leaked for the
process lifetime. Validate by opening and closing the paths instead;
startOnce is the single owner of the per-run file handles.

Part of #120.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Fixes CVE-2026-56852 / GO-2026-5970 (norm.Iter infinite loop on invalid
UTF-8), flagged HIGH by the Trivy scan in CI.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@leontappe
leontappe merged commit 382df09 into master Aug 6, 2026
3 checks passed
@leontappe
leontappe deleted the feat/consistent-job-logging branch August 6, 2026 12:16
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants