Merge pull request #486 from joyent/fanhattan-reopen

config: Introduce logging to file w/ log file re-open on SIGUSR1

config/logger/logging.go

@@ -7,9 +7,12 @@ import (
 	"io"
 	"log"
 	"os"
+	"os/signal"
 	"strings"
+	"syscall"
 	"time"
 
+	"github.com/client9/reopen"
 	"github.com/sirupsen/logrus"
 )
 
@@ -65,8 +68,15 @@ func (l *Config) Init() error {
 		output = os.Stderr
 	case "stdout":
 		output = os.Stdout
-	default:
+	case "":
 		return fmt.Errorf("Unknown output type '%s'", l.Output)
+	default:
+		f, err := reopen.NewFileWriter(l.Output)
+		if err != nil {
+			return fmt.Errorf("Error initializing log file '%s': %s", l.Output, err)
+		}
+		initializeSignal(f)
+		output = f
 	}
 	logrus.SetLevel(level)
 	logrus.SetFormatter(formatter)
@@ -95,3 +105,18 @@ func (f *DefaultLogFormatter) Format(entry *logrus.Entry) ([]byte, error) {
 	// Panic and Fatal are handled by logrus automatically
 	return b.Bytes(), nil
 }
+
+func initializeSignal(f *reopen.FileWriter) {
+	// Handle SIGUSR1
+	//
+	// channel is number of signals needed to catch  (more or less)
+	// we only are working with one here, SIGUSR1
+	sighup := make(chan os.Signal, 1)
+	signal.Notify(sighup, syscall.SIGUSR1)
+	go func() {
+		for {
+			<-sighup
+			f.Reopen()
+		}
+	}()
+}

config/logger/logging_test.go

@@ -1,8 +1,10 @@
 package logger
 
 import (
+	"io/ioutil"
 	"os"
 	"reflect"
+	"strings"
 	"testing"
 
 	"github.com/sirupsen/logrus"
@@ -65,3 +67,32 @@ func TestDefaultFormatterPanic(t *testing.T) {
 	}()
 	logrus.Panicln("Panic Test")
 }
+
+func TestFileLogger(t *testing.T) {
+	// initialize logger
+	filename := "/tmp/test_log"
+	testLog := &Config{
+		Level:  "DEBUG",
+		Format: "text",
+		Output: filename,
+	}
+	err := testLog.Init()
+	if err != nil {
+		t.Errorf("Did not expect error: %v", err)
+	}
+
+	// write a log message
+	logMsg := "this is a test"
+	logrus.Info(logMsg)
+	content, err := ioutil.ReadFile(filename)
+	if err != nil {
+		t.Errorf("Did not expect error: %v", err)
+	}
+	if len(content) == 0 {
+		t.Error("could not write log to file")
+	}
+	logs := string(content)
+	if !strings.Contains(logs, logMsg) {
+		t.Errorf("expected log file to contain '%s', got '%s'", logMsg, logs)
+	}
+}

glide.yaml

@@ -21,3 +21,4 @@ testImport:
   version: v1.1.4
   subpackages:
   - assert
+- package: github.com/client9/reopen

integration_tests/fixtures/app/Dockerfile

@@ -10,6 +10,7 @@ RUN npm install -g json http-server
 COPY build/containerpilot /bin/containerpilot
 COPY containerpilot.json5 /etc/containerpilot.json5
 COPY containerpilot-with-coprocess.json5 /etc/containerpilot-with-coprocess.json5
+COPY containerpilot-with-file-log.json5 /etc/containerpilot-with-file-log.json5
 COPY reload-app.sh /reload-app.sh
 COPY reload-containerpilot.sh /reload-containerpilot.sh
 COPY sensor.sh /sensor.sh

integration_tests/fixtures/app/containerpilot-with-file-log.json5

@@ -0,0 +1,17 @@
+{
+  consul: "consul:8500",
+  logging: {
+    level: "DEBUG",
+    format: "text",
+    output: "/tmp/containerpilot.log"
+  },
+  jobs: [
+    {
+      name: "app",
+      exec: "echo 'hello world!'",
+      when: {
+        interval: 1
+      }
+    }
+  ]
+}

integration_tests/tests/test_reopen/docker-compose.yml

@@ -0,0 +1,10 @@
+app:
+  image: "cpfix_app"
+  mem_limit: 128m
+  volumes:
+    - './test_reopen.sh:/tmp/test_reopen.sh'
+  environment:
+    # needs to be in the container already or we'll potentially
+    # error when we try to rewrite it; update in the future
+    # with an env var change to the args instead
+    - CONTAINERPILOT=/etc/containerpilot-with-file-log.json5

integration_tests/tests/test_reopen/run.sh

@@ -0,0 +1,15 @@
+#!/bin/bash
+
+function finish {
+    result=$?
+    if [[ "$result" -ne 0 ]]; then docker logs "$app" | tee app.log; fi
+    exit $result
+}
+trap finish EXIT
+
+# start up app
+docker-compose up -d app
+app=$(docker-compose ps -q app)
+
+docker exec -i $app /tmp/test_reopen.sh
+

integration_tests/tests/test_reopen/test_reopen.sh

@@ -0,0 +1,31 @@
+#!/bin/bash
+
+CONTAINERPILOT_LOGFILE="/tmp/containerpilot.log"
+CONTAINERPILOT_ROTATEDLOGFILE="/tmp/containerpilot.log.1"
+
+sleep 2
+logs=`cat $CONTAINERPILOT_LOGFILE`
+nb_lines=`cat $CONTAINERPILOT_LOGFILE | wc -l`
+if [ ! -f $CONTAINERPILOT_LOGFILE ] || [[ $logs != *"hello world"* ]]; then
+    exit 1
+fi
+
+#rotate logs
+mv $CONTAINERPILOT_LOGFILE $CONTAINERPILOT_ROTATEDLOGFILE
+
+sleep 2
+nb_lines_rotated=`cat $CONTAINERPILOT_ROTATEDLOGFILE | wc -l`
+if (( $nb_lines_rotated <= $nb_lines )); then
+    exit 1
+fi
+
+#signal containerpilot to reopen file
+kill -SIGUSR1 1
+
+sleep 2
+logs=`cat $CONTAINERPILOT_LOGFILE`
+if [ ! -f $CONTAINERPILOT_LOGFILE ] || [[ $logs != *"hello world"* ]]; then
+    exit 1
+fi
+
+exit 0

sup/sup.go

@@ -30,14 +30,16 @@ func Run() {
 // passes them thru to the ContainerPilot worker process.
 func handleSignals(pid int) {
 	sig := make(chan os.Signal, 1)
-	signal.Notify(sig, syscall.SIGTERM, syscall.SIGINT, syscall.SIGCHLD)
+	signal.Notify(sig, syscall.SIGTERM, syscall.SIGINT, syscall.SIGCHLD, syscall.SIGUSR1)
 	go func() {
 		for signal := range sig {
 			switch signal {
 			case syscall.SIGINT:
 				syscall.Kill(pid, syscall.SIGINT)
 			case syscall.SIGTERM:
 				syscall.Kill(pid, syscall.SIGTERM)
+			case syscall.SIGUSR1:
+				syscall.Kill(pid, syscall.SIGUSR1)
 			case syscall.SIGCHLD:
 				go reap()
 			}