Merge pull request #84 from mittwald/add/std-log-timestamps

add optional timestamping for stdout logs

Author: leontappe

.gitignore

@@ -4,3 +4,4 @@
 /dist
 examples/mittnite.d/local.hcl
 cmd/mittnitectl/mittnitectl
+*.log

README.md

@@ -154,6 +154,24 @@ 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).
+
+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
+  timestampFormat = "RFC3339"  # default
+  customTimestampFormat = ""  # default
+}
+```
+
 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.
   
 ```hcl
@@ -480,3 +498,27 @@ job webserver {
   # ...
 }
 ```
+
+### Timestamp Formats
+
+| Name        | Format                              |
+|-------------|-------------------------------------|
+| Layout      | 01/02 03:04:05PM '06 -0700          |
+| ANSIC       | Mon Jan _2 15:04:05 2006            |                                             
+| UnixDate    | Mon Jan _2 15:04:05 MST 2006        |                                         
+| RubyDate    | Mon Jan 02 15:04:05 -0700 2006      |                                       
+| RFC822      | 02 Jan 06 15:04 MST                 |                                                  
+| RFC822Z     | 02 Jan 06 15:04 -0700               |                    
+| RFC850      | Monday, 02-Jan-06 15:04:05 MST      |                                       
+| RFC1123     | Mon, 02 Jan 2006 15:04:05 MST       |                                        
+| RFC1123Z    | Mon, 02 Jan 2006 15:04:05 -0700     |         
+| RFC3339     | 2006-01-02T15:04:05Z07:00           |                                            
+| RFC3339Nano | 2006-01-02T15:04:05.999999999Z07:00 |                                  
+| Kitchen     | 3:04PM                              |                                                               
+| Stamp       | Jan _2 15:04:05                     |                                                       
+| StampMilli  | Jan _2 15:04:05.000                 |                                                   
+| StampMicro  | Jan _2 15:04:05.000000              |                                                
+| StampNano   | Jan _2 15:04:05.000000000           |                                             
+| DateTime    | 2006-01-02 15:04:05                 |                                                   
+| DateOnly    | 2006-01-02                          |                                                            
+| TimeOnly    | 15:04:05                            |         

examples/oneshots.d/job.sh

@@ -0,0 +1,4 @@
+#!/bin/bash
+
+sleep 10
+exit 0

examples/oneshots.d/job2.sh

@@ -0,0 +1,4 @@
+#!/bin/bash
+
+sleep 5
+exit 0

examples/oneshots.d/one_shot.hcl

@@ -0,0 +1,13 @@
+boot "oneshot" {
+  command = "/bin/bash"
+  args = [
+    "examples/bootjob.d/job.sh"
+  ]
+}
+
+boot "oneshot_two" {
+  command = "/bin/bash"
+  args = [
+    "examples/bootjob.d/job2.sh"
+  ]
+}

examples/timestamps.d/timestamps.hcl

@@ -0,0 +1,49 @@
+job "echoloop_test" {
+  command = "/bin/bash"
+  args = [
+    "-c",
+    "while true ; do echo 'test'; sleep 10; done"
+  ]
+
+  stdout = "test.log"
+  stderr = "test_error.log"
+  enableTimestamps = true
+  timestampFormat = "test"
+}
+
+job "echoloop_custom" {
+  command = "/bin/bash"
+  args = [
+    "-c",
+    "while true ; do echo 'test'; sleep 10; done"
+  ]
+
+  stdout = "test_custom.log"
+  stderr = "test_custom_error.log"
+  enableTimestamps = true
+  customTimestampFormat = "2006-01-02 15:04:05"
+}
+
+job "echoloop_kitchentime" {
+  command = "/bin/bash"
+  args = [
+    "-c",
+    "while true ; do echo 'test'; sleep 10; done"
+  ]
+
+  stdout = "test_kitchentime.log"
+  stderr = "test_kitchentime_error.log"
+  enableTimestamps = true
+  timestampFormat = "Kitchen"
+}
+
+job "echoloop_notime" {
+  command = "/bin/bash"
+  args = [
+    "-c",
+    "while true ; do echo 'test'; sleep 10; done"
+  ]
+
+  stdout = "test_notime.log"
+  stderr = "test_notime_error.log"
+}

internal/config/types.go

@@ -94,8 +94,13 @@ type BaseJobConfig struct {
 	CanFail          bool     `hcl:"canFail" json:"canFail"`
 	Controllable     bool     `hcl:"controllable" json:"controllable"`
 	WorkingDirectory string   `hcl:"workingDirectory" json:"workingDirectory,omitempty"`
-	Stdout           string   `hcl:"stdout" json:"stdout,omitempty"`
-	Stderr           string   `hcl:"stderr" json:"stderr,omitempty"`
+
+	// log config
+	Stdout                string `hcl:"stdout" json:"stdout,omitempty"`
+	Stderr                string `hcl:"stderr" json:"stderr,omitempty"`
+	EnableTimestamps      bool   `hcl:"enableTimestamps" json:"enableTimestamps"`
+	TimestampFormat       string `hcl:"timestampFormat" json:"timestampFormat"` // defaults to RFC3339
+	CustomTimestampFormat string `hcl:"customTimestampFormat" json:"customTimestampFormat"`
 }
 
 type Laziness struct {

pkg/proc/basejob.go

@@ -114,8 +114,29 @@ func (job *baseJob) startOnce(ctx context.Context, process chan<- *os.Process) e
 	cmd := exec.Command(job.Config.Command, job.Config.Args...)
 	cmd.Env = os.Environ()
 	cmd.Dir = job.Config.WorkingDirectory
-	cmd.Stdout = job.stdout
-	cmd.Stderr = job.stderr
+
+	// pipe command's stdout and stderr through timestamp function if timestamps are enabled
+	// otherwise just redirect stdout and err to job.stdout and job.stderr
+	if job.Config.EnableTimestamps {
+		stdoutPipe, err := cmd.StdoutPipe()
+		if err != nil {
+			return fmt.Errorf("failed to create stdout pipe for process: %s", err.Error())
+		}
+		defer stdoutPipe.Close()
+
+		stderrPipe, err := cmd.StderrPipe()
+		if err != nil {
+			return fmt.Errorf("failed to create stderr pipe for process: %s", err.Error())
+		}
+		defer stderrPipe.Close()
+
+		go job.logWithTimestamp(stdoutPipe, job.stdout)
+		go job.logWithTimestamp(stderrPipe, job.stderr)
+	} else {
+		cmd.Stdout = job.stdout
+		cmd.Stderr = job.stderr
+	}
+
 	cmd.SysProcAttr = &syscall.SysProcAttr{
 		Setpgid: true,
 	}
@@ -201,6 +222,40 @@ func (job *baseJob) closeStdFiles() {
 	}
 }
 
+func (job *baseJob) logWithTimestamp(r io.Reader, w io.Writer) {
+	l := log.WithField("job.name", job.Config.Name)
+
+	var layout string
+
+	// has custom timestamp layout?
+	if job.Config.CustomTimestampFormat != "" {
+		layout = job.Config.CustomTimestampFormat
+		l.Infof("using custom timestamp layout '%s'", layout)
+	} else {
+		existingLayout, exists := TimeLayouts[job.Config.TimestampFormat]
+		if !exists {
+			layout = time.RFC3339
+			l.Warningf("unknown timestamp layout '%s', defaulting to RFC3339", job.Config.TimestampFormat)
+		} else {
+			layout = existingLayout
+			l.Infof("logging with timestamp layout '%s'", job.Config.TimestampFormat)
+		}
+	}
+
+	scanner := bufio.NewScanner(r)
+	for scanner.Scan() {
+		timestamp := time.Now().Format(layout)
+		line := fmt.Sprintf("[%s] %s\n", timestamp, scanner.Text())
+		if _, err := w.Write([]byte(line)); err != nil {
+			l.Errorf("error writing log for process: %v\n", err)
+		}
+	}
+
+	if err := scanner.Err(); err != nil {
+		l.Errorf("error reading from process: %v\n", err)
+	}
+}
+
 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 {

pkg/proc/types.go

@@ -2,21 +2,42 @@ package proc
 
 import (
 	"context"
-	"github.com/gorilla/mux"
-	"github.com/gorilla/websocket"
 	"net/http"
 	"os"
 	"os/exec"
 	"sync"
 	"time"
 
+	"github.com/gorilla/mux"
+	"github.com/gorilla/websocket"
+
 	"github.com/mittwald/mittnite/internal/config"
 )
 
 const (
 	ShutdownWaitingTimeSeconds = 10
 )
 
+var TimeLayouts = map[string]string{
+	"RFC3339":     time.RFC3339,
+	"RFC3339Nano": time.RFC3339Nano,
+	"RFC1123":     time.RFC1123,
+	"RFC1123Z":    time.RFC1123Z,
+	"RFC822":      time.RFC822,
+	"RFC822Z":     time.RFC822Z,
+	"ANSIC":       time.ANSIC,
+	"UnixDate":    time.UnixDate,
+	"RubyDate":    time.RubyDate,
+	"Kitchen":     time.Kitchen,
+	"Stamp":       time.Stamp,
+	"StampMilli":  time.StampMilli,
+	"StampMicro":  time.StampMicro,
+	"StampNano":   time.StampNano,
+	"DateTime":    time.DateTime,
+	"DateOnly":    time.DateOnly,
+	"TimeOnly":    time.TimeOnly,
+}
+
 type Runner struct {
 	jobs        []Job
 	bootJobs    []*BootJob