diff --git a/.goreleaser.yml b/.goreleaser.yml index 553b922..ea7256d 100644 --- a/.goreleaser.yml +++ b/.goreleaser.yml @@ -61,6 +61,9 @@ changelog: exclude: - '^docs:' - '^test:' +release: + header: | + > Upgrading across a major version? See [CHANGELOG.md](https://github.com/mittwald/mittnite/blob/master/CHANGELOG.md) for the breaking changes. dockers: - image_templates: diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 0000000..3814131 --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,25 @@ +# Changelog + +Release notes are generated from commits by goreleaser; this file documents the breaking changes of major releases. + +## v2.0.0 + +### Breaking changes + +- **Job output decoration is on by default.** Every line of every job and boot job is prefixed with `[] [] `. Opt out globally with `mittnite up --job-log-timestamps=false --job-log-name-prefix=false` or `MITTNITE_JOB_LOG_TIMESTAMPS=0` / `MITTNITE_JOB_LOG_NAME_PREFIX=0`; opt out per job with `enableTimestamps = false` / `enableNamePrefix = false` (explicit per-job values always win, as before). +- **Decorated output is forwarded line-wise through mittnite.** Single lines longer than 64 KiB are forwarded in chunks, and other jobs' output may interleave between the chunks of such a line on a shared target. Jobs that write binary data or machine-parsed output (e.g. JSON log lines consumed by a strict collector) to stdout/stderr should opt out per job — with both options disabled, the output streams are attached directly and stay byte-identical to v1. +- **`MITTNITE_JOB_LOG_*` semantics changed:** unset now means *enabled*; unparsable values fall back to *enabled*, with a startup warning naming the effective value. +- **Watch `preCommand`/`postCommand` output is now decorated** with the owning job's timestamp/name prefix. +- The Docker tags `stable` and `latest` on quay.io move to v2 with this release — pin `quay.io/mittwald/mittnite:v1` to defer the migration. + +### Other changes + +- `Layout` and `RFC850` are now accepted `timestampFormat` values; both were documented but previously warned "unknown timestamp format" and fell back to RFC3339. +- The "logging with timestamp layout" message moved from info to debug level — it fired once per job start *and restart*. +- Successful `canFail` boot jobs no longer log a spurious "job failed, but is allowed to fail" warning with an empty error. +- Persistent write errors on a broken log target are logged once per failure streak instead of once per output line. +- Running `mittnite` without a subcommand falls back to `up` again — it crashed on a nil function since v1.x (broken in `cdb2ecf`, 2023). + +## v1 and earlier + +See the [GitHub releases](https://github.com/mittwald/mittnite/releases). diff --git a/README.md b/README.md index 4f51ed8..2097074 100644 --- a/README.md +++ b/README.md @@ -33,6 +33,7 @@ It offers the following features: - [Render a file on startup](#render-a-file-on-startup) - [Wait until a Redis connection is possible](#wait-until-a-redis-connection-is-possible) - [More examples](#more-examples) +- [Migration to v2](#migration-to-v2) - [mittnitectl](#mittnitectl) @@ -51,14 +52,16 @@ Usage: mittnite [command] Available Commands: + completion Generate the autocompletion script for the specified shell help Help about any command - renderfiles - up + renderfiles Renders configuration files + up Render config files, start probes and processes version Show extended information about the current version of mittnite Flags: -c, --config-dir string set directory to where your .hcl-configs are located (default "/etc/mittnite.d") -h, --help help for mittnite + --profile enable pprof http server Use "mittnite [command] --help" for more information about a command. ``` @@ -151,34 +154,30 @@ job "foo" { } ``` -Additionally, you can enable timestamps for the output of a job using `enableTimestamps` and specify a custom format using `timestampFormat`. - -Formats are named after their constant name in the Golang [`time` package](https://pkg.go.dev/time#pkg-constants) (lookup table at the bottom). The default is `RFC3339`. - -You can also specify your own format by setting `customTimestampFormat` to a custom format string like "2006-01-02 15:04:05". Whatever is set in `timestampFormat` will be ignored in that case. - -With `enableNamePrefix`, each output line is prefixed with the job's name. When both options are enabled, the timestamp comes first: +Job output is decorated by default: every output line of every job is prefixed with a timestamp and the job's name, in that order: ``` [2026-07-24T10:28:52Z] [foo] some output line ``` +The two parts are controlled per job with `enableTimestamps` and `enableNamePrefix`. Timestamp formats are named after their constant name in the Golang [`time` package](https://pkg.go.dev/time#pkg-constants) (lookup table at the bottom) and selected with `timestampFormat`; the default is `RFC3339`. You can also specify your own format by setting `customTimestampFormat` to a custom format string like "2006-01-02 15:04:05". Whatever is set in `timestampFormat` will be ignored in that case. + ```hcl job "foo" { command = "/usr/local/bin/foo" args = ["bar"] stdout = "/tmp/foo.log" stderr = "/tmp/foo-errors.log" - enableTimestamps = true + enableTimestamps = true # default timestampFormat = "RFC3339" # default - customTimestampFormat = "" # default - enableNamePrefix = true # defaults to false + customTimestampFormat = "" # default + enableNamePrefix = true # default } ``` -Both options can also be enabled globally for all jobs (including boot jobs) with `mittnite up --job-log-timestamps --job-log-name-prefix`, or via the environment variables `MITTNITE_JOB_LOG_TIMESTAMPS` and `MITTNITE_JOB_LOG_NAME_PREFIX`. An explicit per-job `enableTimestamps` / `enableNamePrefix` — including an explicit `false` — always wins over the global switch. +Both options can be disabled globally for all jobs (including boot jobs) with `mittnite up --job-log-timestamps=false --job-log-name-prefix=false`, or by setting the environment variables `MITTNITE_JOB_LOG_TIMESTAMPS` / `MITTNITE_JOB_LOG_NAME_PREFIX` to `0`. An explicit per-job `enableTimestamps` / `enableNamePrefix` — including an explicit `false` — always wins over the global switch. -With either option enabled, output is forwarded line by line. Single lines longer than 64 KiB are forwarded in multiple chunks; on a shared target, output of other jobs or streams may interleave between the chunks of such a line. +With either option enabled, output is forwarded line by line. Single lines longer than 64 KiB are forwarded in multiple chunks; on a shared target, output of other jobs or streams may interleave between the chunks of such a line. Jobs that write binary data — or machine-parsed output such as JSON log lines, when the consumer cannot be taught the prefix — should disable both options: with both disabled, the job's output streams are attached directly and stay byte-identical. You can configure a Job to watch files and to send a signal to the managed process if that file changes. This can be used, for example, to send a `SIGHUP` to a process to reload its configuration file when it changes. @@ -228,6 +227,8 @@ job "foo" { } ``` +The output of `preCommand`/`postCommand` is decorated with the owning job's timestamp/name prefix, following the same job-level settings as the job's own output. + You can also configure a Job to start its process only on the first incoming request (a bit like [systemd's socket activation](https://www.freedesktop.org/software/systemd/man/systemd.socket.html)). In order to configure this, you need a `listener` and a `lazy` configuration: ```hcl @@ -267,7 +268,7 @@ boot "setup" { } ``` -Boot jobs write to mittnite's stdout/stderr and support the same log options as regular jobs (`stdout`, `stderr`, `enableTimestamps`, `timestampFormat`, `customTimestampFormat`, `enableNamePrefix`). +Boot jobs write to mittnite's stdout/stderr and support the same log options as regular jobs (`stdout`, `stderr`, `enableTimestamps`, `timestampFormat`, `customTimestampFormat`, `enableNamePrefix`) — including the same on-by-default decoration. #### File @@ -449,6 +450,22 @@ probe redis { ### More examples More example files can be found in the [examples directory](examples/) +## Migration to v2 + +See [CHANGELOG.md](CHANGELOG.md) for the full list of breaking changes. + +The headline change: **job output decoration is on by default**. Every output line of every job and boot job is prefixed with `[] [] `, and output is forwarded line by line through mittnite instead of being written directly by the process. + +To keep v1-identical output: + +- **Globally**: run `mittnite up --job-log-timestamps=false --job-log-name-prefix=false`, or set the environment variables `MITTNITE_JOB_LOG_TIMESTAMPS=0` and `MITTNITE_JOB_LOG_NAME_PREFIX=0`. +- **Per job**: set `enableTimestamps = false` and `enableNamePrefix = false` in the job's configuration — explicit per-job values always win over the global switches. A job with both options disabled writes to its output targets directly again, byte-identical to v1. +- **Defer the migration**: pin the image tag `quay.io/mittwald/mittnite:v1` (the `stable` and `latest` tags move to v2). + +Jobs that emit binary data or machine-parsed output (e.g. JSON log lines consumed by a strict log collector) should opt out per job. + +Also note: unset or unparsable `MITTNITE_JOB_LOG_*` environment variables now mean *enabled*; an unparsable value is warned about at startup together with the effective value. + ## mittnitectl `mittnitectl` can be used to control the mittnite process as long as the required API is enabled (`mittnite up --api`). diff --git a/cmd/root.go b/cmd/root.go index 3b31019..19a4889 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -38,9 +38,11 @@ var rootCmd = &cobra.Command{ }() } }, - Run: func(cmd *cobra.Command, args []string) { + // delegate to up's RunE — up defines no Run, so calling up.Run here (as + // this fallback did until v2) crashed on a nil function + RunE: func(cmd *cobra.Command, args []string) error { log.Warn("Running 'mittnite' without any arguments - defaulting to 'up'. This behaviour may change in future releases!") - up.Run(cmd, args) + return up.RunE(cmd, args) }, } diff --git a/cmd/root_test.go b/cmd/root_test.go new file mode 100644 index 0000000..ffb4c82 --- /dev/null +++ b/cmd/root_test.go @@ -0,0 +1,17 @@ +package cmd + +import ( + "testing" + + "github.com/stretchr/testify/require" +) + +// The bare-mittnite fallback must delegate to up's RunE: up defines no Run, +// so a Run-based delegation calls a nil function — exactly the crash the v2 +// fallback repair removed. +func TestRootFallbackDelegatesToUpRunE(t *testing.T) { + require.Nil(t, up.Run, "up switched to RunE in cdb2ecf; a Run delegation would be a nil call") + require.NotNil(t, up.RunE) + require.Nil(t, rootCmd.Run, "the fallback must use RunE, matching up") + require.NotNil(t, rootCmd.RunE) +} diff --git a/cmd/up.go b/cmd/up.go index 5ecebec..bd26c5e 100644 --- a/cmd/up.go +++ b/cmd/up.go @@ -23,6 +23,11 @@ const ( envJobLogTimestamps = "MITTNITE_JOB_LOG_TIMESTAMPS" envJobLogNamePrefix = "MITTNITE_JOB_LOG_NAME_PREFIX" + + // job output decoration is on by default since v2.0.0; see the + // migration section in the README + defaultJobLogTimestamps = true + defaultJobLogNamePrefix = true ) var ( @@ -48,23 +53,32 @@ func init() { up.PersistentFlags().BoolVarP(&apiEnabled, "api", "", false, "enables the api for remote or cli controlling") up.PersistentFlags().StringVarP(&apiListenAddress, "api-listen-address", "", DefaultAPIAddress, fmt.Sprintf("listen address for the api. Defaults to %q", DefaultAPIAddress)) up.PersistentFlags().BoolVarP(&keepRunning, "keep-running", "k", false, "keep mittnite running even if no job is running anymore") - up.PersistentFlags().BoolVar(&jobLogTimestamps, "job-log-timestamps", envBool(envJobLogTimestamps), "prefix each output line of every job with a timestamp (RFC3339 unless the job configures a format); per-job enableTimestamps wins (env: "+envJobLogTimestamps+")") - up.PersistentFlags().BoolVar(&jobLogNamePrefix, "job-log-name-prefix", envBool(envJobLogNamePrefix), "prefix each output line of every job with the job's name; per-job enableNamePrefix wins (env: "+envJobLogNamePrefix+")") + up.PersistentFlags().BoolVar(&jobLogTimestamps, "job-log-timestamps", envBool(envJobLogTimestamps, defaultJobLogTimestamps), "prefix each output line of every job with a timestamp (RFC3339 unless the job configures a format); disable globally with --job-log-timestamps=false or "+envJobLogTimestamps+"=0; an explicit per-job enableTimestamps wins") + up.PersistentFlags().BoolVar(&jobLogNamePrefix, "job-log-name-prefix", envBool(envJobLogNamePrefix, defaultJobLogNamePrefix), "prefix each output line of every job with the job's name; disable globally with --job-log-name-prefix=false or "+envJobLogNamePrefix+"=0; an explicit per-job enableNamePrefix wins") } // envBool interprets an environment variable as a boolean flag default; unset -// or unparsable values count as false (the latter are warned about in Run, -// since logging is not set up yet when flag defaults are evaluated). -func envBool(key string) bool { +// or unparsable values fall back to defaultValue (the latter are warned about +// in Run, since logging is not set up yet when flag defaults are evaluated). +func envBool(key string, defaultValue bool) bool { v, err := strconv.ParseBool(os.Getenv(key)) - return err == nil && v + if err != nil { + return defaultValue + } + return v } +// warnUnparsableEnvBools runs after flag parsing, so it reports the effective +// flag value — the built-in default, unless an explicit --job-log-* flag +// overrode it. func warnUnparsableEnvBools() { - for _, key := range []string{envJobLogTimestamps, envJobLogNamePrefix} { + for key, effective := range map[string]bool{ + envJobLogTimestamps: jobLogTimestamps, + envJobLogNamePrefix: jobLogNamePrefix, + } { if v, ok := os.LookupEnv(key); ok { if _, err := strconv.ParseBool(v); err != nil { - log.Warnf("ignoring environment variable %s: %q is not a boolean value", key, v) + log.Warnf("ignoring environment variable %s: %q is not a boolean value, the effective value is %t", key, v, effective) } } } diff --git a/cmd/up_test.go b/cmd/up_test.go index da924a6..3ce8278 100644 --- a/cmd/up_test.go +++ b/cmd/up_test.go @@ -1,6 +1,8 @@ package cmd import ( + "fmt" + "os" "testing" log "github.com/sirupsen/logrus" @@ -9,23 +11,33 @@ import ( ) func TestEnvBool(t *testing.T) { - cases := map[string]bool{ + parsable := map[string]bool{ "1": true, "true": true, "TRUE": true, "t": true, "0": false, "false": false, - "": false, - "yes": false, // not a strconv.ParseBool value, counts as false } - - for value, expected := range cases { - t.Setenv("MITTNITE_ENVBOOL_TEST", value) - require.Equal(t, expected, envBool("MITTNITE_ENVBOOL_TEST"), "value %q", value) + fallsBack := []string{ + "", + "yes", // not a strconv.ParseBool value } - require.False(t, envBool("MITTNITE_ENVBOOL_TEST_UNSET")) + for _, defaultValue := range []bool{true, false} { + for value, expected := range parsable { + t.Setenv("MITTNITE_ENVBOOL_TEST", value) + require.Equal(t, expected, envBool("MITTNITE_ENVBOOL_TEST", defaultValue), + "value %q, default %t", value, defaultValue) + } + for _, value := range fallsBack { + t.Setenv("MITTNITE_ENVBOOL_TEST", value) + require.Equal(t, defaultValue, envBool("MITTNITE_ENVBOOL_TEST", defaultValue), + "value %q must fall back to the default", value) + } + require.Equal(t, defaultValue, envBool("MITTNITE_ENVBOOL_TEST_UNSET", defaultValue), + "unset must fall back to the default") + } } func TestWarnUnparsableEnvBools(t *testing.T) { @@ -45,4 +57,23 @@ func TestWarnUnparsableEnvBools(t *testing.T) { } require.Len(t, warnings, 1, "only the unparsable variable should be warned about") require.Contains(t, warnings[0], envJobLogTimestamps) + require.Contains(t, warnings[0], fmt.Sprintf("the effective value is %t", jobLogTimestamps), + "the warning must state the effective value, since unparsable now means on") +} + +// Job output decoration is on by default since v2.0.0. The flag defaults are +// fixed at package init from the environment, so this only asserts the +// built-in default when the variables are absent from the test process. +func TestJobLogFlagDefaultsAreTrue(t *testing.T) { + for _, key := range []string{envJobLogTimestamps, envJobLogNamePrefix} { + if _, ok := os.LookupEnv(key); ok { + t.Skipf("%s is set; flag defaults were derived from it at package init", key) + } + } + + for _, name := range []string{"job-log-timestamps", "job-log-name-prefix"} { + flag := up.PersistentFlags().Lookup(name) + require.NotNil(t, flag) + require.Equal(t, "true", flag.DefValue, "--%s must default to on", name) + } } diff --git a/examples/timestamps.d/timestamps.hcl b/examples/timestamps.d/timestamps.hcl index f4c25ed..2674d02 100644 --- a/examples/timestamps.d/timestamps.hcl +++ b/examples/timestamps.d/timestamps.hcl @@ -8,7 +8,7 @@ job "echoloop_test" { stdout = "test.log" stderr = "test_error.log" enableTimestamps = true - timestampFormat = "test" + timestampFormat = "RFC1123" } job "echoloop_custom" { @@ -37,6 +37,7 @@ job "echoloop_kitchentime" { timestampFormat = "Kitchen" } +# opts out of the default timestamps only; the name prefix stays on job "echoloop_notime" { command = "/bin/bash" args = [ @@ -46,7 +47,24 @@ job "echoloop_notime" { stdout = "test_notime.log" stderr = "test_notime_error.log" + enableTimestamps = false } + +# opts out of the default decoration entirely: output is written to the +# targets directly, byte-identical +job "echoloop_raw" { + command = "/bin/bash" + args = [ + "-c", + "while true ; do echo 'test'; sleep 10; done" + ] + + stdout = "test_raw.log" + stderr = "test_raw_error.log" + enableTimestamps = false + enableNamePrefix = false +} + job "echoloop_nameprefix" { command = "/bin/bash" args = [ diff --git a/internal/config/types.go b/internal/config/types.go index e971a75..4e6fb68 100644 --- a/internal/config/types.go +++ b/internal/config/types.go @@ -107,13 +107,16 @@ type BaseJobConfig struct { } // TimestampsEnabled reports whether the job's output lines should be prefixed -// with a timestamp; an unset enableTimestamps counts as disabled. +// with a timestamp. The global default is expected to have been materialized +// onto an unset enableTimestamps first (Ignition.ApplyJobLogDefaults, which +// `up` runs at startup); a still-nil value counts as disabled. func (c *BaseJobConfig) TimestampsEnabled() bool { return c.EnableTimestamps != nil && *c.EnableTimestamps } // NamePrefixEnabled reports whether the job's output lines should be prefixed -// with the job name; an unset enableNamePrefix counts as disabled. +// with the job name; like TimestampsEnabled, it reads the materialized value +// and a still-nil enableNamePrefix counts as disabled. func (c *BaseJobConfig) NamePrefixEnabled() bool { return c.EnableNamePrefix != nil && *c.EnableNamePrefix } diff --git a/pkg/proc/basejob.go b/pkg/proc/basejob.go index cd3b88d..f7cb313 100644 --- a/pkg/proc/basejob.go +++ b/pkg/proc/basejob.go @@ -305,12 +305,13 @@ func (job *baseJob) closeStdFiles() { } // resolveTimestampLayout determines the timestamp layout for the job's log -// output and logs the choice once per process start. timestamp.layout always -// carries the effective Go time layout; timestamp.format the configured key. +// output and logs the choice at debug level once per process start; only an +// unknown configured format warns. timestamp.layout always carries the +// effective Go time layout; timestamp.format the configured key. func (job *baseJob) resolveTimestampLayout(l *log.Entry) string { if job.Config.CustomTimestampFormat != "" { l.WithField("timestamp.layout", job.Config.CustomTimestampFormat). - Info("logging with custom timestamp layout") + Debug("logging with custom timestamp layout") return job.Config.CustomTimestampFormat } @@ -330,7 +331,7 @@ func (job *baseJob) resolveTimestampLayout(l *log.Entry) string { l.WithField("timestamp.format", format). WithField("timestamp.layout", layout). - Info("logging with timestamp layout") + Debug("logging with timestamp layout") return layout } @@ -354,6 +355,7 @@ func (job *baseJob) forwardOutput(r io.ReadCloser, w io.Writer, timestampLayout var timeBuffer []byte var lineBuffer bytes.Buffer continuation := false + writeFailed := false for { line, isPrefix, err := reader.ReadLine() @@ -390,12 +392,103 @@ func (job *baseJob) forwardOutput(r io.ReadCloser, w io.Writer, timestampLayout w = io.Discard continue } - l.WithError(err).Error("error writing log line for process") + // a persistently broken target would otherwise be logged at + // the child's write rate; log once per failure streak and keep + // trying, so a recovered target resumes forwarding + if !writeFailed { + writeFailed = true + l.WithError(err).Error("error writing log line for process, suppressing repeated errors until a write succeeds") + } continue } + writeFailed = false } } +// runCommandWithJobDecoration runs the already-configured cmd, forwarding its +// output to the given targets with the job's timestamp/name decoration, so +// auxiliary commands (watch pre/post commands) are attributable like the +// job's own output. Without decoration — or when pipe creation fails — the +// targets are attached directly. The forwarders get the same bounded drain +// as startOnce; a child outliving the command keeps a forwarder running past +// the return, which is safe because the targets are the process-wide streams +// and never closed. +func (job *baseJob) runCommandWithJobDecoration(cmd *exec.Cmd, stdout, stderr *os.File) error { + runDirect := func() error { + cmd.Stdout = stdout + cmd.Stderr = stderr + return cmd.Run() + } + + if !job.Config.TimestampsEnabled() && !job.Config.NamePrefixEnabled() { + return runDirect() + } + + l := log.WithField("job.name", job.Config.Name) + + stdoutReader, stdoutWriter, err := os.Pipe() + if err != nil { + return runDirect() + } + stderrReader, stderrWriter, err := os.Pipe() + if err != nil { + stdoutReader.Close() + stdoutWriter.Close() + return runDirect() + } + + cmd.Stdout = stdoutWriter + cmd.Stderr = stderrWriter + + var layout string + if job.Config.TimestampsEnabled() { + layout = job.resolveTimestampLayout(l) + } + + var namePrefix []byte + if job.Config.NamePrefixEnabled() { + namePrefix = []byte("[" + job.Config.Name + "] ") + } + + var forwardersDone sync.WaitGroup + forwardersDone.Add(2) + go func() { + defer forwardersDone.Done() + job.forwardOutput(stdoutReader, stdout, layout, namePrefix) + }() + go func() { + defer forwardersDone.Done() + job.forwardOutput(stderrReader, stderr, layout, namePrefix) + }() + + runErr := cmd.Start() + + // the started child holds duplicates of the pipe write ends; close ours + // so the forwarders see EOF once all child-side writers are gone + // (immediately, if the start failed) + stdoutWriter.Close() + stderrWriter.Close() + + if runErr == nil { + runErr = cmd.Wait() + } + + // bounded drain, like startOnce: EOF arrives right after cmd.Wait in the + // normal case, the cap only bites when the command forked children that + // keep the pipe write ends open + done := make(chan struct{}) + go func() { + forwardersDone.Wait() + close(done) + }() + select { + case <-done: + case <-time.After(time.Second): + } + + return runErr +} + func (job *baseJob) readStdFile(ctx context.Context, wg *sync.WaitGroup, filePath string, outChan chan []byte, errChan chan error, follow bool, tailLen int) { stdFile, err := os.OpenFile(filePath, os.O_RDONLY, 0o666) if err != nil { diff --git a/pkg/proc/basejob_test.go b/pkg/proc/basejob_test.go index cb0e0d3..316d7ee 100644 --- a/pkg/proc/basejob_test.go +++ b/pkg/proc/basejob_test.go @@ -197,7 +197,8 @@ func TestBootJobWithUnopenableLogTargetHonorsCanFail(t *testing.T) { } // An unset timestampFormat is the documented default (RFC3339) and must not -// trigger the unknown-format warning. +// trigger the unknown-format warning — or any other log line above debug +// level, since the resolution runs on every job (re)start. func TestResolveTimestampLayoutDefaultsToRFC3339WithoutWarning(t *testing.T) { logHook := logtest.NewGlobal() defer logHook.Reset() @@ -207,10 +208,35 @@ func TestResolveTimestampLayoutDefaultsToRFC3339WithoutWarning(t *testing.T) { require.Equal(t, time.RFC3339, layout) for _, entry := range logHook.AllEntries() { - require.NotEqual(t, log.WarnLevel, entry.Level, "unexpected warning: %s", entry.Message) + require.GreaterOrEqual(t, entry.Level, log.DebugLevel, + "layout resolution must not log above debug: %s", entry.Message) } } +// The chosen layout is logged at debug level only, so restart loops do not +// spam the info log with one layout line per start. +func TestResolveTimestampLayoutLogsLayoutAtDebugOnly(t *testing.T) { + logHook := logtest.NewGlobal() + defer logHook.Reset() + + previousLevel := log.GetLevel() + log.SetLevel(log.DebugLevel) + t.Cleanup(func() { log.SetLevel(previousLevel) }) + + job := &baseJob{Config: &config.BaseJobConfig{ + Name: "debug-layout-job", + TimestampFormat: "Kitchen", + }} + job.resolveTimestampLayout(log.WithField("job.name", job.Config.Name)) + + var messages []string + for _, entry := range logHook.AllEntries() { + require.Equal(t, log.DebugLevel, entry.Level, "unexpected level for: %s", entry.Message) + messages = append(messages, entry.Message) + } + require.Contains(t, messages, "logging with timestamp layout") +} + func TestResolveTimestampLayoutWarnsOnUnknownFormat(t *testing.T) { logHook := logtest.NewGlobal() defer logHook.Reset() @@ -270,6 +296,121 @@ func TestForwardOutputHandlesOverlongLines(t *testing.T) { } } +// A job with decoration explicitly disabled — the opt-out state after +// ApplyJobLogDefaults materialized false onto it — keeps the raw fd +// passthrough. The output deliberately has no trailing newline: the line +// forwarder would append one, so byte-identical output here proves nothing +// was piped through mittnite, not just that the decoration was empty. +func TestStartOnceRawPassthroughWhenBothOptionsExplicitlyDisabled(t *testing.T) { + stdoutPath := filepath.Join(t.TempDir(), "stdout.log") + + job := &baseJob{} + job.init(&config.BaseJobConfig{ + Name: "raw-job", + Command: "printf", + Args: []string{"hello"}, + EnableTimestamps: boolPtr(false), + EnableNamePrefix: boolPtr(false), + Stdout: stdoutPath, + }) + + require.NoError(t, job.startOnce(context.Background(), nil)) + + content, err := os.ReadFile(stdoutPath) + require.NoError(t, err) + require.Equal(t, "hello", string(content)) +} + +// ApplyJobLogDefaults composed with the job constructors and startOnce: jobs +// and boot jobs without explicit log options pick up the flipped global +// defaults and emit fully decorated output. (The cmd/up wiring that passes +// the flag values — after config generation — is covered by E2E runs, not +// here.) +func TestDefaultDecorationEndToEnd(t *testing.T) { + dir := t.TempDir() + jobOut := filepath.Join(dir, "job.log") + bootOut := filepath.Join(dir, "boot.log") + + ignition := &config.Ignition{ + Jobs: []config.JobConfig{{ + BaseJobConfig: config.BaseJobConfig{ + Name: "default-job", + Command: "echo", + Args: []string{"hello"}, + Stdout: jobOut, + }, + }}, + BootJobs: []config.BootJobConfig{{ + BaseJobConfig: config.BaseJobConfig{ + Name: "default-boot", + Command: "echo", + Args: []string{"ahoi"}, + Stdout: bootOut, + }, + }}, + } + ignition.ApplyJobLogDefaults(true, true) + + commonJob, err := NewCommonJob(&ignition.Jobs[0]) + require.NoError(t, err) + require.NoError(t, commonJob.startOnce(context.Background(), nil)) + + bootJob, err := NewBootJob(&ignition.BootJobs[0]) + require.NoError(t, err) + require.NoError(t, bootJob.Run(context.Background())) + + pattern := `^\[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(Z|[+-]\d{2}:\d{2})\] \[%s\] %s\n$` + content, err := os.ReadFile(jobOut) + require.NoError(t, err) + require.Regexp(t, fmt.Sprintf(pattern, "default-job", "hello"), string(content)) + + content, err = os.ReadFile(bootOut) + require.NoError(t, err) + require.Regexp(t, fmt.Sprintf(pattern, "default-boot", "ahoi"), string(content)) +} + +// flakyWriter fails or passes each write according to the per-call results +// list (nil = success); writes beyond the list succeed. +type flakyWriter struct { + results []error + buf bytes.Buffer + calls int +} + +func (w *flakyWriter) Write(p []byte) (int, error) { + defer func() { w.calls++ }() + if w.calls < len(w.results) && w.results[w.calls] != nil { + return 0, w.results[w.calls] + } + w.buf.Write(p) + return len(p), nil +} + +// A persistently failing log target must not be logged at the child's write +// rate: one error per failure streak, and forwarding resumes when the target +// recovers. +func TestForwardOutputLogsPersistentWriteErrorsOncePerStreak(t *testing.T) { + logHook := logtest.NewGlobal() + defer logHook.Reset() + + brokenTarget := fmt.Errorf("target broken") + w := &flakyWriter{results: []error{brokenTarget, brokenTarget, nil, brokenTarget, brokenTarget}} + + job := &baseJob{Config: &config.BaseJobConfig{Name: "flaky-target-job"}} + job.forwardOutput(io.NopCloser(strings.NewReader("one\ntwo\nthree\nfour\nfive\n")), + w, "", []byte("[flaky-target-job] ")) + + errorCount := 0 + for _, entry := range logHook.AllEntries() { + if entry.Level == log.ErrorLevel { + errorCount++ + } + } + require.Equal(t, 2, errorCount, "expected one error per failure streak") + require.Equal(t, "[flaky-target-job] three\n", w.buf.String(), + "writes must still be attempted after failures") +} + // When the flush wait times out because a lingering child keeps the pipes // open, the forwarder goroutines outlive startOnce; a restart then reassigns // job.stdout/job.stderr via CreateAndOpenStdFile, so the forwarders must have diff --git a/pkg/proc/job_boot.go b/pkg/proc/job_boot.go index 0ecb008..5f678f3 100644 --- a/pkg/proc/job_boot.go +++ b/pkg/proc/job_boot.go @@ -7,10 +7,11 @@ import ( ) func (job *BootJob) Run(ctx context.Context) error { - l := log.WithField("job.name", job.Config.Name) err := job.startOnce(ctx, nil) - if job.Config.CanFail { - l.WithError(err).Warn("job failed, but is allowed to fail") + if err != nil && job.Config.CanFail { + log.WithField("job.name", job.Config.Name). + WithError(err). + Warn("job failed, but is allowed to fail") return nil } return err diff --git a/pkg/proc/job_boot_test.go b/pkg/proc/job_boot_test.go new file mode 100644 index 0000000..82f9c6f --- /dev/null +++ b/pkg/proc/job_boot_test.go @@ -0,0 +1,54 @@ +package proc + +import ( + "context" + "testing" + + log "github.com/sirupsen/logrus" + logtest "github.com/sirupsen/logrus/hooks/test" + "github.com/stretchr/testify/require" + + "github.com/mittwald/mittnite/internal/config" +) + +func newCanFailBootJob(t *testing.T, command string) *BootJob { + t.Helper() + + job, err := NewBootJob(&config.BootJobConfig{ + BaseJobConfig: config.BaseJobConfig{ + Name: "can-fail-boot-job", + Command: command, + CanFail: true, + }, + }) + require.NoError(t, err) + return job +} + +// A successful canFail boot job must not log the "allowed to fail" warning. +func TestBootJobCanFailDoesNotWarnOnSuccess(t *testing.T) { + logHook := logtest.NewGlobal() + defer logHook.Reset() + + require.NoError(t, newCanFailBootJob(t, "true").Run(context.Background())) + + for _, entry := range logHook.AllEntries() { + require.NotEqual(t, log.WarnLevel, entry.Level, "unexpected warning: %s", entry.Message) + } +} + +// A failing canFail boot job still warns and reports success. +func TestBootJobCanFailStillWarnsOnFailure(t *testing.T) { + logHook := logtest.NewGlobal() + defer logHook.Reset() + + require.NoError(t, newCanFailBootJob(t, "false").Run(context.Background())) + + var warnings []string + for _, entry := range logHook.AllEntries() { + if entry.Level == log.WarnLevel { + warnings = append(warnings, entry.Message) + } + } + require.Contains(t, warnings, "job failed, but is allowed to fail") +} diff --git a/pkg/proc/job_common.go b/pkg/proc/job_common.go index 3a46ab3..8c07dff 100644 --- a/pkg/proc/job_common.go +++ b/pkg/proc/job_common.go @@ -239,8 +239,6 @@ func (job *CommonJob) executeWatchCommand(watchCmd *config.WatchCommand) error { return errors.New("command is missing") } cmd := exec.Command(watchCmd.Command, watchCmd.Args...) - cmd.Stdout = os.Stdout - cmd.Stderr = os.Stderr cmd.Env = os.Environ() if watchCmd.Env != nil { @@ -249,7 +247,7 @@ func (job *CommonJob) executeWatchCommand(watchCmd *config.WatchCommand) error { log.WithField("job.name", job.Config.Name). Info("executing watch command") - return cmd.Run() + return job.runCommandWithJobDecoration(cmd, os.Stdout, os.Stderr) } func (job *CommonJob) crashLoopSleep(ctx context.Context, duration time.Duration) { diff --git a/pkg/proc/job_common_test.go b/pkg/proc/job_common_test.go new file mode 100644 index 0000000..360d608 --- /dev/null +++ b/pkg/proc/job_common_test.go @@ -0,0 +1,141 @@ +package proc + +import ( + "os" + "os/exec" + "path/filepath" + "testing" + "time" + + "github.com/stretchr/testify/require" + + "github.com/mittwald/mittnite/internal/config" +) + +func watchCommandTestTargets(t *testing.T) (*os.File, *os.File) { + t.Helper() + + dir := t.TempDir() + stdout, err := os.Create(filepath.Join(dir, "stdout")) + require.NoError(t, err) + stderr, err := os.Create(filepath.Join(dir, "stderr")) + require.NoError(t, err) + t.Cleanup(func() { + stdout.Close() + stderr.Close() + }) + return stdout, stderr +} + +func watchCommandTestJob(t *testing.T, timestamps, namePrefix bool) *CommonJob { + t.Helper() + + job, err := NewCommonJob(&config.JobConfig{ + BaseJobConfig: config.BaseJobConfig{ + Name: "watch-job", + Command: "true", + EnableTimestamps: boolPtr(timestamps), + EnableNamePrefix: boolPtr(namePrefix), + }, + }) + require.NoError(t, err) + return job +} + +const watchDecoratedLinePattern = `^\[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(Z|[+-]\d{2}:\d{2})\] \[watch-job\] ` + +// Watch pre/post command output carries the same timestamp/name decoration +// as the job's own output, on both streams, and is fully flushed when the +// command returns. +func TestWatchCommandOutputIsDecorated(t *testing.T) { + job := watchCommandTestJob(t, true, true) + stdout, stderr := watchCommandTestTargets(t) + + cmd := exec.Command("sh", "-c", "echo changed; echo oops >&2") + require.NoError(t, job.runCommandWithJobDecoration(cmd, stdout, stderr)) + + outBytes, err := os.ReadFile(stdout.Name()) + require.NoError(t, err) + errBytes, err := os.ReadFile(stderr.Name()) + require.NoError(t, err) + + require.Regexp(t, watchDecoratedLinePattern+"changed\n$", string(outBytes)) + require.Regexp(t, watchDecoratedLinePattern+"oops\n$", string(errBytes)) +} + +// With only one option enabled the other must not leak in: a name-prefix-only +// job decorates watch command output with the prefix alone. +func TestWatchCommandOutputNamePrefixOnly(t *testing.T) { + job := watchCommandTestJob(t, false, true) + stdout, stderr := watchCommandTestTargets(t) + + cmd := exec.Command("sh", "-c", "echo changed") + require.NoError(t, job.runCommandWithJobDecoration(cmd, stdout, stderr)) + + outBytes, err := os.ReadFile(stdout.Name()) + require.NoError(t, err) + require.Equal(t, "[watch-job] changed\n", string(outBytes)) +} + +// A job with decoration explicitly disabled runs its watch commands with the +// targets attached directly. The command output deliberately has no trailing +// newline: the line forwarder would append one, so byte-identical output here +// proves the raw path, not just an undecorated forwarder. +func TestWatchCommandOutputRawWhenUndecorated(t *testing.T) { + job := watchCommandTestJob(t, false, false) + stdout, stderr := watchCommandTestTargets(t) + + cmd := exec.Command("sh", "-c", "printf changed; printf oops >&2") + require.NoError(t, job.runCommandWithJobDecoration(cmd, stdout, stderr)) + + outBytes, err := os.ReadFile(stdout.Name()) + require.NoError(t, err) + errBytes, err := os.ReadFile(stderr.Name()) + require.NoError(t, err) + + require.Equal(t, "changed", string(outBytes)) + require.Equal(t, "oops", string(errBytes)) +} + +// When the command cannot be started, the parent-side pipe write ends must +// still be closed so the forwarders see EOF immediately — the error returns +// fast instead of blocking on the full bounded drain. +func TestRunCommandWithJobDecorationStartFailureReturnsFast(t *testing.T) { + job := watchCommandTestJob(t, true, true) + stdout, stderr := watchCommandTestTargets(t) + + cmd := exec.Command("/nonexistent-mittnite-test-binary") + start := time.Now() + require.Error(t, job.runCommandWithJobDecoration(cmd, stdout, stderr)) + require.Less(t, time.Since(start), 900*time.Millisecond) + + outBytes, err := os.ReadFile(stdout.Name()) + require.NoError(t, err) + require.Empty(t, outBytes) +} + +// executeWatchCommand itself must route through the decoration helper — this +// exercises the real wiring by swapping the process-wide streams it targets. +// (Package tests run sequentially; nothing else writes to os.Stdout here, and +// logrus holds its own reference to the original stderr.) +func TestExecuteWatchCommandRoutesThroughDecoration(t *testing.T) { + job := watchCommandTestJob(t, true, true) + stdout, stderr := watchCommandTestTargets(t) + + origStdout, origStderr := os.Stdout, os.Stderr + os.Stdout, os.Stderr = stdout, stderr + defer func() { + os.Stdout, os.Stderr = origStdout, origStderr + }() + + err := job.executeWatchCommand(&config.WatchCommand{ + Command: "sh", + Args: []string{"-c", "echo changed"}, + }) + os.Stdout, os.Stderr = origStdout, origStderr + require.NoError(t, err) + + outBytes, readErr := os.ReadFile(stdout.Name()) + require.NoError(t, readErr) + require.Regexp(t, watchDecoratedLinePattern+"changed\n$", string(outBytes)) +} diff --git a/pkg/proc/types.go b/pkg/proc/types.go index 243d691..81f9b42 100644 --- a/pkg/proc/types.go +++ b/pkg/proc/types.go @@ -24,8 +24,10 @@ var TimeLayouts = map[string]string{ "RFC3339Nano": time.RFC3339Nano, "RFC1123": time.RFC1123, "RFC1123Z": time.RFC1123Z, + "RFC850": time.RFC850, "RFC822": time.RFC822, "RFC822Z": time.RFC822Z, + "Layout": time.Layout, "ANSIC": time.ANSIC, "UnixDate": time.UnixDate, "RubyDate": time.RubyDate, diff --git a/pkg/proc/types_test.go b/pkg/proc/types_test.go new file mode 100644 index 0000000..7588c6f --- /dev/null +++ b/pkg/proc/types_test.go @@ -0,0 +1,35 @@ +package proc + +import ( + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +// TestTimeLayoutsCoverAllNamedGoTimeLayouts pins TimeLayouts to the full set +// of named layout constants in the time package, which is also the set the +// README's timestamp format table documents. +func TestTimeLayoutsCoverAllNamedGoTimeLayouts(t *testing.T) { + require.Equal(t, map[string]string{ + "Layout": time.Layout, + "ANSIC": time.ANSIC, + "UnixDate": time.UnixDate, + "RubyDate": time.RubyDate, + "RFC822": time.RFC822, + "RFC822Z": time.RFC822Z, + "RFC850": time.RFC850, + "RFC1123": time.RFC1123, + "RFC1123Z": time.RFC1123Z, + "RFC3339": time.RFC3339, + "RFC3339Nano": time.RFC3339Nano, + "Kitchen": time.Kitchen, + "Stamp": time.Stamp, + "StampMilli": time.StampMilli, + "StampMicro": time.StampMicro, + "StampNano": time.StampNano, + "DateTime": time.DateTime, + "DateOnly": time.DateOnly, + "TimeOnly": time.TimeOnly, + }, TimeLayouts) +}