Job Logging v2

.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:

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 `[<RFC3339 timestamp>] [<job name>] `. 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).

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)
 <!-- END doctoc generated TOC please keep comment here to allow auto update -->
 
@@ -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 `[<RFC3339 timestamp>] [<job name>] `, 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`).

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)
 	},
 }
 

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)
+}

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)
 			}
 		}
 	}

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)
+	}
 }

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 = [

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
 }