src/lib/syslog/go/logger_test.go

// Copyright 2018 The Fuchsia Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

// +build !build_with_native_toolchain

package syslog_test

import (
	"bytes"
	"encoding/binary"
	"fmt"
	"io/ioutil"
	"os"
	"path/filepath"
	"strings"
	"syscall/zx"
	"testing"
	"unicode/utf8"

	"fidl/fuchsia/logger"

	syslog "go.fuchsia.dev/fuchsia/src/lib/syslog/go"
)

const format = "integer: %d"

var pid = uint64(os.Getpid())

func TestLogSimple(t *testing.T) {
	actual := bytes.Buffer{}
	options := syslog.LogInitOptions{
		MinSeverityForFileAndLineInfo: syslog.ErrorLevel,
		Writer:                        &actual,
	}
	logger, err := syslog.NewLogger(options)
	if err != nil {
		t.Fatal(err)
	}
	logger.Infof(format, 10)
	expected := "INFO: integer: 10\n"
	got := string(actual.Bytes())
	if !strings.HasSuffix(got, expected) {
		t.Errorf("%q should have ended in %q", got, expected)
	}
	if !strings.Contains(got, fmt.Sprintf("[%d]", pid)) {
		t.Errorf("%q should contains %d", got, pid)
	}
}

func TestLogSimple_Socket(t *testing.T) {
	sin, sout, err := zx.NewSocket(zx.SocketDatagram)
	if err != nil {
		t.Fatal(err)
	}
	options := syslog.LogInitOptions{
		MinSeverityForFileAndLineInfo: syslog.ErrorLevel,
		Writer:                        &bytes.Buffer{},
		Socket:                        sout,
	}
	logger, err := syslog.NewLogger(options)
	if err != nil {
		t.Fatal(err)
	}
	logger.Infof(format, 10)
	checkoutput(t, sin, fmt.Sprintf(format, 10), syslog.InfoLevel)
}

func setup(t *testing.T, tags ...string) (zx.Socket, *syslog.Logger) {
	sin, sout, err := zx.NewSocket(zx.SocketDatagram)
	if err != nil {
		t.Fatal(err)
	}
	log, err := syslog.NewLogger(syslog.LogInitOptions{
		LogLevel:                      syslog.InfoLevel,
		MinSeverityForFileAndLineInfo: syslog.ErrorLevel,
		Socket:                        sout,
		Tags:                          tags,
	})
	if err != nil {
		t.Fatal(err)
	}
	return sin, log
}

func checkoutput(t *testing.T, sin zx.Socket, expectedMsg string, severity syslog.LogLevel, tags ...string) {
	var data [logger.MaxDatagramLenBytes]byte
	n, err := sin.Read(data[:], 0)
	if err != nil {
		t.Fatal(err)
	}
	if n <= 32 {
		t.Fatalf("got invalid data: %v", data[:n])
	}
	gotpid := binary.LittleEndian.Uint64(data[0:8])
	gotTid := binary.LittleEndian.Uint64(data[8:16])
	gotTime := binary.LittleEndian.Uint64(data[16:24])
	gotSeverity := int32(binary.LittleEndian.Uint32(data[24:28]))
	gotDroppedLogs := int32(binary.LittleEndian.Uint32(data[28:32]))

	if pid != gotpid {
		t.Errorf("pid error, got: %d, want: %d", gotpid, pid)
	}

	if 0 != gotTid {
		t.Errorf("tid error, got: %d, want: %d", gotTid, 0)
	}

	if int32(severity) != gotSeverity {
		t.Errorf("severity error, got: %d, want: %d", gotSeverity, severity)
	}

	if gotTime <= 0 {
		t.Errorf("time %d should be greater than zero", gotTime)
	}

	if 0 != gotDroppedLogs {
		t.Errorf("dropped logs error, got: %d, want: %d", gotDroppedLogs, 0)
	}
	pos := 32
	for i, tag := range tags {
		length := len(tag)
		if data[pos] != byte(length) {
			t.Fatalf("tag iteration %d: expected data to be %d at pos %d, got %d", i, length, pos, data[pos])
		}
		pos = pos + 1
		gotTag := string(data[pos : pos+length])
		if tag != gotTag {
			t.Fatalf("tag iteration %d: expected tag %q , got %q", i, tag, gotTag)
		}
		pos = pos + length
	}

	if data[pos] != 0 {
		t.Fatalf("byte before msg start should be zero, got: %d, %v", data[pos], data[32:n])
	}

	msgGot := string(data[pos+1 : n-1])
	if expectedMsg != msgGot {
		t.Fatalf("expected msg:%q, got %q", expectedMsg, msgGot)
	}
	if data[n-1] != 0 {
		t.Fatalf("last byte should be zero, got: %d, %v", data[pos], data[32:n])
	}
}

func TestLogWithLocalTag(t *testing.T) {
	sin, log := setup(t)
	log.InfoTf("local_tag", format, 10)
	expectedMsg := fmt.Sprintf(format, 10)
	checkoutput(t, sin, expectedMsg, syslog.InfoLevel, "local_tag")
}

func TestLogWithGlobalTags(t *testing.T) {
	sin, log := setup(t, "gtag1", "gtag2")
	log.InfoTf("local_tag", format, 10)
	expectedMsg := fmt.Sprintf(format, 10)
	checkoutput(t, sin, expectedMsg, syslog.InfoLevel, "gtag1", "gtag2", "local_tag")
}

func TestLoggerSeverity(t *testing.T) {
	sin, log := setup(t)
	log.SetSeverity(syslog.WarningLevel)
	log.Infof(format, 10)
	_, err := sin.Read(make([]byte, 0), 0)
	if err, ok := err.(*zx.Error); !ok || err.Status != zx.ErrShouldWait {
		t.Fatal(err)
	}
	log.Warnf(format, 10)
	expectedMsg := fmt.Sprintf(format, 10)
	checkoutput(t, sin, expectedMsg, syslog.WarningLevel)
}

func TestLoggerVerbosity(t *testing.T) {
	sin, log := setup(t)
	log.VLogf(syslog.DebugVerbosity, format, 10)
	_, err := sin.Read(make([]byte, 0), 0)
	if err, ok := err.(*zx.Error); !ok || err.Status != zx.ErrShouldWait {
		t.Fatal(err)
	}
	log.SetVerbosity(syslog.DebugVerbosity)
	log.VLogf(syslog.DebugVerbosity, format, 10)
	expectedMsg := fmt.Sprintf(format, 10)
	checkoutput(t, sin, expectedMsg, (syslog.InfoLevel - 1))
}

func TestGlobalTagLimits(t *testing.T) {
	options := syslog.LogInitOptions{
		Writer: os.Stdout,
	}
	var tags [logger.MaxTags + 1]string
	for i := 0; i < len(tags); i++ {
		tags[i] = "a"
	}
	options.Tags = tags[:]
	if _, err := syslog.NewLogger(options); err == nil || !strings.Contains(err.Error(), "too many tags") {
		t.Fatalf("unexpected error: %s", err)
	}
	options.Tags = tags[:logger.MaxTags]
	var tag [logger.MaxTagLenBytes + 1]byte
	for i := 0; i < len(tag); i++ {
		tag[i] = 65
	}
	options.Tags[1] = string(tag[:])
	if _, err := syslog.NewLogger(options); err == nil || !strings.Contains(err.Error(), "tag too long") {
		t.Fatalf("unexpected error: %s", err)
	}
}

func TestLocalTagLimits(t *testing.T) {
	sin, log := setup(t)
	var tag [logger.MaxTagLenBytes + 1]byte
	for i := 0; i < len(tag); i++ {
		tag[i] = 65
	}
	log.InfoTf(string(tag[:]), format, 10)
	expectedMsg := fmt.Sprintf(format, 10)
	checkoutput(t, sin, expectedMsg, syslog.InfoLevel, string(tag[:logger.MaxTagLenBytes]))
}

func TestLogToWriterWhenSocketCloses(t *testing.T) {
	sin, log := setup(t, "gtag1", "gtag2")
	sin.Close()
	old := os.Stderr
	defer func() {
		os.Stderr = old
	}()

	f, err := os.Create(filepath.Join(t.TempDir(), "syslog-test"))
	if err != nil {
		t.Fatal(err)
	}
	defer func() {
		f.Close()
	}()
	os.Stderr = f
	log.InfoTf("local_tag", format, 10)
	if err := f.Sync(); err != nil {
		t.Fatal(err)
	}
	expectedMsg := fmt.Sprintf("[0][gtag1, gtag2, local_tag] INFO: %s\n", fmt.Sprintf(format, 10))
	content, err := ioutil.ReadFile(f.Name())
	os.Stderr = old
	if err != nil {
		t.Fatal(err)
	}
	got := string(content)
	if !strings.HasSuffix(got, expectedMsg) {
		t.Fatalf("%q should have ended in %q", got, expectedMsg)
	}
}

func TestMessageLenLimit(t *testing.T) {
	sin, log := setup(t)
	// 1 for starting and ending null bytes.
	msgLen := int(logger.MaxDatagramLenBytes) - 32 - 1 - 1

	const stripped = '𠜎'
	// Ensure only part of stripped fits.
	msg := strings.Repeat("x", msgLen-(utf8.RuneLen(stripped)-1)) + string(stripped)
	switch err := log.Infof(msg).(type) {
	case *syslog.ErrMsgTooLong:
		if err.Msg != string(stripped) {
			t.Fatalf("unexpected truncation: %s", err.Msg)
		}
	default:
		t.Fatalf("unexpected error: %v", err)
	}

	const ellipsis = "..."
	expectedMsg := msg[:msgLen-len(ellipsis)] + ellipsis
	checkoutput(t, sin, expectedMsg, syslog.InfoLevel)
}