caddy/logging_lifecycle_test.go

// Copyright 2015 Matthew Holt and The Caddy Authors
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
//     http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

package caddy

import (
	"bytes"
	"context"
	"encoding/json"
	"errors"
	"fmt"
	"io"
	"log"
	"strings"
	"sync"
	"testing"
)

func TestLoggingSinkReloadLifecycle(t *testing.T) {
	baseline, originalDefault := prepareLoggingLifecycle(t)
	a, sinkA, _ := lifecycleLogging(t, true)
	cancelA := provisionLifecycleLogging(t, a)
	log.Print("first sink")
	if !strings.Contains(sinkA.contents(), "first sink") {
		t.Fatal("standard logger did not reach initial sink")
	}

	b, sinkB, _ := lifecycleLogging(t, true)
	cancelB := provisionLifecycleLogging(t, b)
	cancelA()
	log.Print("replacement sink")
	if !strings.Contains(sinkB.contents(), "replacement sink") || !sinkA.isClosed() {
		t.Fatal("old config cleanup undid the replacement sink or leaked its writer")
	}
	if strings.Contains(sinkA.contents(), "replacement sink") {
		t.Fatal("replacement log reached old sink")
	}

	c, _, _ := lifecycleLogging(t, false)
	cancelC := provisionLifecycleLogging(t, c)
	cancelB()
	log.Print("sink removed")
	if !strings.Contains(baseline.contents(), "baseline: sink removed") {
		t.Fatalf("removed sink did not restore original logger: %s", baseline.contents())
	}
	if strings.Contains(sinkB.contents(), "sink removed") || !sinkB.isClosed() {
		t.Fatal("removed sink received another log or leaked its writer")
	}

	d, sinkD, _ := lifecycleLogging(t, true)
	cancelD := provisionLifecycleLogging(t, d)
	cancelC()
	log.Print("sink reintroduced")
	if !strings.Contains(sinkD.contents(), "sink reintroduced") {
		t.Fatal("sinkless config cleanup undid newer sink")
	}
	cancelD()
	if log.Writer() != baseline || log.Prefix() != "baseline: " || log.Flags() != log.Lmsgprefix {
		t.Fatal("final cleanup did not restore original standard logger state")
	}
	if defaultLogger != originalDefault {
		t.Fatal("final cleanup did not restore original Caddy logger")
	}
}

func TestLoggingFailedProvisioningRestoresOwner(t *testing.T) {
	for _, sink := range []bool{false, true} {
		t.Run(fmt.Sprintf("active_sink=%t", sink), func(t *testing.T) {
			testLoggingFailedProvisioningRestoresOwner(t, sink)
		})
	}
}

func testLoggingFailedProvisioningRestoresOwner(t *testing.T, sink bool) {
	baseline, _ := prepareLoggingLifecycle(t)
	active, activeSink, activeDefault := lifecycleLogging(t, sink)
	activeWriter := activeSink
	if activeWriter == nil {
		activeWriter = baseline
	}
	provisionLifecycleLogging(t, active)
	originalDefault := defaultLogger
	for _, stage := range []string{"sink", "default", "custom", "storage"} {
		for _, sink := range []bool{false, true} {
			if stage == "sink" && !sink {
				continue
			}
			t.Run(stage+map[bool]string{false: "/without_sink", true: "/with_sink"}[sink], func(t *testing.T) {
				failed, failedSink, failedDefault := lifecycleLogging(t, sink)
				switch stage {
				case "sink":
					failed.Sink.Level = "invalid"
				case "default":
					failed.Logs[DefaultLoggerName].Level = "invalid"
				case "custom":
					failed.Logs["broken"] = &CustomLog{BaseLog: BaseLog{Level: "invalid"}}
				}
				var cancel context.CancelFunc
				if stage == "storage" {
					ctx, err := provisionContext(&Config{
						Logging:    failed,
						StorageRaw: json.RawMessage(`{"module":"nonexistent"}`),
					}, false)
					if err == nil {
						t.Fatal("expected storage provisioning failure")
					}
					cancel = func() { ctx.cfg.cancelFunc(nil) }
				} else {
					ctx, cancelContext := NewContext(Context{Context: context.Background()})
					cancel = cancelContext
					if err := failed.openLogs(ctx); err == nil {
						t.Fatal("expected logging provisioning failure")
					}
				}
				t.Cleanup(cancel)
				cancel()
				cancel()
				log.Print("after failed provisioning")
				Log().Info("Caddy logger after failed provisioning")
				if !strings.Contains(activeWriter.contents(), "after failed provisioning") {
					t.Fatal("failure did not restore active sink")
				}
				if defaultLogger != originalDefault || activeWriter.isClosed() || activeDefault.isClosed() {
					t.Fatal("failure replaced or closed active loggers")
				}
				if stage != "sink" && !failedDefault.isClosed() {
					t.Fatal("failed configuration's default writer leaked")
				}
				if sink && !failedSink.isClosed() {
					t.Fatal("failed configuration's sink writer leaked")
				}
			})
		}
	}
}

func prepareLoggingLifecycle(t *testing.T) (*lifecycleLogWriter, *defaultCustomLog) {
	t.Helper()
	originalWriter, originalFlags, originalPrefix := log.Writer(), log.Flags(), log.Prefix()
	defaultLoggerMu.Lock()
	originalDefault := defaultLogger
	originalOwners, originalBaseline := loggingOwners, loggingBaseline
	loggingOwners = nil
	defaultLoggerMu.Unlock()
	baseline := new(lifecycleLogWriter)
	log.SetOutput(baseline)
	log.SetPrefix("baseline: ")
	log.SetFlags(log.Lmsgprefix)
	t.Cleanup(func() {
		defaultLoggerMu.Lock()
		if len(loggingOwners) != 0 {
			t.Error("configuration logger ownership leaked")
		}
		loggingOwners, loggingBaseline = originalOwners, originalBaseline
		defaultLogger = originalDefault
		defaultLoggerMu.Unlock()
		log.SetOutput(originalWriter)
		log.SetFlags(originalFlags)
		log.SetPrefix(originalPrefix)
	})
	return baseline, originalDefault
}

func lifecycleLogging(t *testing.T, sink bool) (*Logging, *lifecycleLogWriter, *lifecycleLogWriter) {
	t.Helper()
	defaultWriter := new(lifecycleLogWriter)
	defaultWriter.key = fmt.Sprintf("%s/default/%p", t.Name(), defaultWriter)
	logging := &Logging{Logs: map[string]*CustomLog{
		DefaultLoggerName: {BaseLog: BaseLog{writerOpener: defaultWriter}},
	}}
	var sinkWriter *lifecycleLogWriter
	if sink {
		sinkWriter = new(lifecycleLogWriter)
		sinkWriter.key = fmt.Sprintf("%s/sink/%p", t.Name(), sinkWriter)
		logging.Sink = &SinkLog{BaseLog: BaseLog{writerOpener: sinkWriter}}
	}
	return logging, sinkWriter, defaultWriter
}

func provisionLifecycleLogging(t *testing.T, logging *Logging) context.CancelFunc {
	t.Helper()
	ctx, cancel := NewContext(Context{Context: context.Background()})
	t.Cleanup(cancel)
	if err := logging.openLogs(ctx); err != nil {
		t.Fatal(err)
	}
	return cancel
}

type lifecycleLogWriter struct {
	mu     sync.Mutex
	buffer bytes.Buffer
	key    string
	closed bool
}

func (w *lifecycleLogWriter) WriterKey() string                   { return w.key }
func (w *lifecycleLogWriter) String() string                      { return w.key }
func (w *lifecycleLogWriter) OpenWriter() (io.WriteCloser, error) { return w, nil }
func (w *lifecycleLogWriter) Write(p []byte) (int, error) {
	w.mu.Lock()
	defer w.mu.Unlock()
	if w.closed {
		return 0, errors.New("write to closed lifecycle log")
	}
	return w.buffer.Write(p)
}
func (w *lifecycleLogWriter) Close() error {
	w.mu.Lock()
	defer w.mu.Unlock()
	w.closed = true
	return nil
}
func (w *lifecycleLogWriter) contents() string {
	w.mu.Lock()
	defer w.mu.Unlock()
	return w.buffer.String()
}
func (w *lifecycleLogWriter) isClosed() bool {
	w.mu.Lock()
	defer w.mu.Unlock()
	return w.closed
}