log_test.go

Documentation: github.com/letsencrypt/boulder/log

     1  package log
     2  
     3  import (
     4  	"bytes"
     5  	"fmt"
     6  	"log/syslog"
     7  	"net"
     8  	"os"
     9  	"strings"
    10  	"sync"
    11  	"testing"
    12  	"time"
    13  
    14  	"github.com/jmhodges/clock"
    15  	"github.com/letsencrypt/boulder/test"
    16  )
    17  
    18  const stdoutLevel = 7
    19  const syslogLevel = 7
    20  
    21  func setup(t *testing.T) *impl {
    22  	// Write all logs to UDP on a high port so as to not bother the system
    23  	// which is running the test
    24  	writer, err := syslog.Dial("udp", "127.0.0.1:65530", syslog.LOG_INFO|syslog.LOG_LOCAL0, "")
    25  	test.AssertNotError(t, err, "Could not construct syslog object")
    26  
    27  	logger, err := New(writer, stdoutLevel, syslogLevel)
    28  	test.AssertNotError(t, err, "Could not construct syslog object")
    29  	impl, ok := logger.(*impl)
    30  	if !ok {
    31  		t.Fatalf("Wrong type returned from New: %T", logger)
    32  	}
    33  	return impl
    34  }
    35  
    36  func TestConstruction(t *testing.T) {
    37  	t.Parallel()
    38  	_ = setup(t)
    39  }
    40  
    41  func TestSingleton(t *testing.T) {
    42  	t.Parallel()
    43  	log1 := Get()
    44  	test.AssertNotNil(t, log1, "Logger shouldn't be nil")
    45  
    46  	log2 := Get()
    47  	test.AssertEquals(t, log1, log2)
    48  
    49  	audit := setup(t)
    50  
    51  	// Should not work
    52  	err := Set(audit)
    53  	test.AssertError(t, err, "Can't re-set")
    54  
    55  	// Verify no change
    56  	log4 := Get()
    57  
    58  	// Verify that log4 != log3
    59  	test.AssertNotEquals(t, log4, audit)
    60  
    61  	// Verify that log4 == log2 == log1
    62  	test.AssertEquals(t, log4, log2)
    63  	test.AssertEquals(t, log4, log1)
    64  }
    65  
    66  func TestConstructionNil(t *testing.T) {
    67  	t.Parallel()
    68  	_, err := New(nil, stdoutLevel, syslogLevel)
    69  	test.AssertError(t, err, "Nil shouldn't be permitted.")
    70  }
    71  
    72  func TestEmit(t *testing.T) {
    73  	t.Parallel()
    74  	log := setup(t)
    75  
    76  	log.AuditInfo("test message")
    77  }
    78  
    79  func TestEmitEmpty(t *testing.T) {
    80  	t.Parallel()
    81  	log := setup(t)
    82  
    83  	log.AuditInfo("")
    84  }
    85  
    86  func TestStdoutLogger(t *testing.T) {
    87  	stdout := bytes.NewBuffer(nil)
    88  	stderr := bytes.NewBuffer(nil)
    89  	logger := &impl{
    90  		&stdoutWriter{
    91  			prefix:    "prefix ",
    92  			level:     7,
    93  			clkFormat: "2006-01-02",
    94  			clk:       clock.NewFake(),
    95  			stdout:    stdout,
    96  			stderr:    stderr,
    97  		},
    98  	}
    99  
   100  	logger.AuditErr("Error Audit")
   101  	logger.Warning("Warning log")
   102  	logger.Info("Info log")
   103  
   104  	test.AssertEquals(t, stdout.String(), "1970-01-01 prefix 6 log.test pcbo7wk Info log\n")
   105  	test.AssertEquals(t, stderr.String(), "1970-01-01 prefix 3 log.test 46_ghQg [AUDIT] Error Audit\n1970-01-01 prefix 4 log.test 97r2xAw Warning log\n")
   106  }
   107  
   108  func TestSyslogMethods(t *testing.T) {
   109  	t.Parallel()
   110  	impl := setup(t)
   111  
   112  	impl.AuditInfo("audit-logger_test.go: audit-info")
   113  	impl.AuditErr("audit-logger_test.go: audit-err")
   114  	impl.Debug("audit-logger_test.go: debug")
   115  	impl.Err("audit-logger_test.go: err")
   116  	impl.Info("audit-logger_test.go: info")
   117  	impl.Warning("audit-logger_test.go: warning")
   118  	impl.AuditInfof("audit-logger_test.go: %s", "audit-info")
   119  	impl.AuditErrf("audit-logger_test.go: %s", "audit-err")
   120  	impl.Debugf("audit-logger_test.go: %s", "debug")
   121  	impl.Errf("audit-logger_test.go: %s", "err")
   122  	impl.Infof("audit-logger_test.go: %s", "info")
   123  	impl.Warningf("audit-logger_test.go: %s", "warning")
   124  }
   125  
   126  func TestAuditObject(t *testing.T) {
   127  	t.Parallel()
   128  
   129  	log := NewMock()
   130  
   131  	// Test a simple object
   132  	log.AuditObject("Prefix", "String")
   133  	if len(log.GetAllMatching("[AUDIT]")) != 1 {
   134  		t.Errorf("Failed to audit log simple object")
   135  	}
   136  
   137  	// Test a system object
   138  	log.Clear()
   139  	log.AuditObject("Prefix", t)
   140  	if len(log.GetAllMatching("[AUDIT]")) != 1 {
   141  		t.Errorf("Failed to audit log system object")
   142  	}
   143  
   144  	// Test a complex object
   145  	log.Clear()
   146  	type validObj struct {
   147  		A string
   148  		B string
   149  	}
   150  	var valid = validObj{A: "B", B: "C"}
   151  	log.AuditObject("Prefix", valid)
   152  	if len(log.GetAllMatching("[AUDIT]")) != 1 {
   153  		t.Errorf("Failed to audit log complex object")
   154  	}
   155  
   156  	// Test logging an unserializable object
   157  	log.Clear()
   158  	type invalidObj struct {
   159  		A chan string
   160  	}
   161  
   162  	var invalid = invalidObj{A: make(chan string)}
   163  	log.AuditObject("Prefix", invalid)
   164  	if len(log.GetAllMatching("[AUDIT]")) != 1 {
   165  		t.Errorf("Failed to audit log unserializable object %v", log.GetAllMatching("[AUDIT]"))
   166  	}
   167  }
   168  
   169  func TestTransmission(t *testing.T) {
   170  	t.Parallel()
   171  
   172  	l, err := newUDPListener("127.0.0.1:0")
   173  	test.AssertNotError(t, err, "Failed to open log server")
   174  	defer func() {
   175  		err = l.Close()
   176  		test.AssertNotError(t, err, "listener.Close returned error")
   177  	}()
   178  
   179  	fmt.Printf("Going to %s\n", l.LocalAddr().String())
   180  	writer, err := syslog.Dial("udp", l.LocalAddr().String(), syslog.LOG_INFO|syslog.LOG_LOCAL0, "")
   181  	test.AssertNotError(t, err, "Failed to find connect to log server")
   182  
   183  	impl, err := New(writer, stdoutLevel, syslogLevel)
   184  	test.AssertNotError(t, err, "Failed to construct audit logger")
   185  
   186  	data := make([]byte, 128)
   187  
   188  	impl.AuditInfo("audit-logger_test.go: audit-info")
   189  	_, _, err = l.ReadFrom(data)
   190  	test.AssertNotError(t, err, "Failed to find packet")
   191  
   192  	impl.AuditErr("audit-logger_test.go: audit-err")
   193  	_, _, err = l.ReadFrom(data)
   194  	test.AssertNotError(t, err, "Failed to find packet")
   195  
   196  	impl.Debug("audit-logger_test.go: debug")
   197  	_, _, err = l.ReadFrom(data)
   198  	test.AssertNotError(t, err, "Failed to find packet")
   199  
   200  	impl.Err("audit-logger_test.go: err")
   201  	_, _, err = l.ReadFrom(data)
   202  	test.AssertNotError(t, err, "Failed to find packet")
   203  
   204  	impl.Info("audit-logger_test.go: info")
   205  	_, _, err = l.ReadFrom(data)
   206  	test.AssertNotError(t, err, "Failed to find packet")
   207  
   208  	impl.Warning("audit-logger_test.go: warning")
   209  	_, _, err = l.ReadFrom(data)
   210  	test.AssertNotError(t, err, "Failed to find packet")
   211  
   212  	impl.AuditInfof("audit-logger_test.go: %s", "audit-info")
   213  	_, _, err = l.ReadFrom(data)
   214  	test.AssertNotError(t, err, "Failed to find packet")
   215  
   216  	impl.AuditErrf("audit-logger_test.go: %s", "audit-err")
   217  	_, _, err = l.ReadFrom(data)
   218  	test.AssertNotError(t, err, "Failed to find packet")
   219  
   220  	impl.Debugf("audit-logger_test.go: %s", "debug")
   221  	_, _, err = l.ReadFrom(data)
   222  	test.AssertNotError(t, err, "Failed to find packet")
   223  
   224  	impl.Errf("audit-logger_test.go: %s", "err")
   225  	_, _, err = l.ReadFrom(data)
   226  	test.AssertNotError(t, err, "Failed to find packet")
   227  
   228  	impl.Infof("audit-logger_test.go: %s", "info")
   229  	_, _, err = l.ReadFrom(data)
   230  	test.AssertNotError(t, err, "Failed to find packet")
   231  
   232  	impl.Warningf("audit-logger_test.go: %s", "warning")
   233  	_, _, err = l.ReadFrom(data)
   234  	test.AssertNotError(t, err, "Failed to find packet")
   235  }
   236  
   237  func TestSyslogLevels(t *testing.T) {
   238  	t.Parallel()
   239  
   240  	l, err := newUDPListener("127.0.0.1:0")
   241  	test.AssertNotError(t, err, "Failed to open log server")
   242  	defer func() {
   243  		err = l.Close()
   244  		test.AssertNotError(t, err, "listener.Close returned error")
   245  	}()
   246  
   247  	fmt.Printf("Going to %s\n", l.LocalAddr().String())
   248  	writer, err := syslog.Dial("udp", l.LocalAddr().String(), syslog.LOG_INFO|syslog.LOG_LOCAL0, "")
   249  	test.AssertNotError(t, err, "Failed to find connect to log server")
   250  
   251  	// create a logger with syslog level debug
   252  	impl, err := New(writer, stdoutLevel, int(syslog.LOG_DEBUG))
   253  	test.AssertNotError(t, err, "Failed to construct audit logger")
   254  
   255  	data := make([]byte, 512)
   256  
   257  	// debug messages should be sent to the logger
   258  	impl.Debug("log_test.go: debug")
   259  	_, _, err = l.ReadFrom(data)
   260  	test.AssertNotError(t, err, "Failed to find packet")
   261  	test.Assert(t, strings.Contains(string(data), "log_test.go: debug"), "Failed to find log message")
   262  
   263  	// create a logger with syslog level info
   264  	impl, err = New(writer, stdoutLevel, int(syslog.LOG_INFO))
   265  	test.AssertNotError(t, err, "Failed to construct audit logger")
   266  
   267  	// debug messages should not be sent to the logger
   268  	impl.Debug("log_test.go: debug")
   269  	n, _, err := l.ReadFrom(data)
   270  	if n != 0 && err == nil {
   271  		t.Error("Failed to withhold debug log message")
   272  	}
   273  }
   274  
   275  func newUDPListener(addr string) (*net.UDPConn, error) {
   276  	l, err := net.ListenPacket("udp", addr)
   277  	if err != nil {
   278  		return nil, err
   279  	}
   280  	err = l.SetDeadline(time.Now().Add(100 * time.Millisecond))
   281  	if err != nil {
   282  		return nil, err
   283  	}
   284  	err = l.SetReadDeadline(time.Now().Add(100 * time.Millisecond))
   285  	if err != nil {
   286  		return nil, err
   287  	}
   288  	err = l.SetWriteDeadline(time.Now().Add(100 * time.Millisecond))
   289  	if err != nil {
   290  		return nil, err
   291  	}
   292  	return l.(*net.UDPConn), nil
   293  }
   294  
   295  // TestStdoutFailure tests that audit logging with a bothWriter panics if stdout
   296  // becomes unavailable.
   297  func TestStdoutFailure(t *testing.T) {
   298  	// Save the stdout fd so we can restore it later
   299  	saved := os.Stdout
   300  
   301  	// Create a throw-away pipe FD to replace stdout with
   302  	_, w, err := os.Pipe()
   303  	test.AssertNotError(t, err, "failed to create pipe")
   304  	os.Stdout = w
   305  
   306  	// Setup the logger
   307  	log := setup(t)
   308  
   309  	// Close Stdout so that the fmt.Printf in bothWriter's logAtLevel
   310  	// function will return an err on next log.
   311  	err = os.Stdout.Close()
   312  	test.AssertNotError(t, err, "failed to close stdout")
   313  
   314  	// Defer a function that will check if there was a panic to recover from. If
   315  	// there wasn't then the test should fail, we were able to AuditInfo when
   316  	// Stdout was inoperable.
   317  	defer func() {
   318  		if recovered := recover(); recovered == nil {
   319  			t.Errorf("log.AuditInfo with Stdout closed did not panic")
   320  		}
   321  
   322  		// Restore stdout so that subsequent tests don't fail
   323  		os.Stdout = saved
   324  	}()
   325  
   326  	// Try to audit log something
   327  	log.AuditInfo("This should cause a panic, stdout is closed!")
   328  }
   329  
   330  func TestLogAtLevelEscapesNewlines(t *testing.T) {
   331  	var buf bytes.Buffer
   332  	w := &bothWriter{sync.Mutex{},
   333  		nil,
   334  		&stdoutWriter{
   335  			stdout: &buf,
   336  			clk:    clock.NewFake(),
   337  			level:  6,
   338  		},
   339  		-1,
   340  	}
   341  	w.logAtLevel(6, "foo\nbar")
   342  
   343  	test.Assert(t, strings.Contains(buf.String(), "foo\\nbar"), "failed to escape newline")
   344  }
   345
View as plain text