bin/logger/tests/go/src/logger_integration_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.

package main

import (
	"app/context"
	"bytes"
	"crypto/rand"
	"fmt"
	"io/ioutil"
	"log"
	"math/big"
	"os"
	"os/exec"
	"strings"
	"syslog/logger"
	"testing"
	"time"
)

const (
	loglistener = "/bin/log_listener"
)

func TestFullStack(t *testing.T) {
	if _, err := os.Stat(loglistener); err != nil {
		t.Fatalf("error stating log listener: %s", err)
	}

	tag := genTag()

	ctx := context.CreateFromStartupInfo()
	if err := logger.InitDefaultLoggerWithTags(ctx.Connector(), tag); err != nil {
		t.Fatal(err)
	}
	if err := logger.Infof("integer: %d", 10); err != nil {
		t.Fatal(err)
	}

	expected := fmt.Sprintf("[0][%s] INFO: integer: 10\n", tag)

	t.Run("LogListenerToStdout", func(t *testing.T) {
		testToStdout(t, tag, expected)
	})

	t.Run("LogListenerToFile", func(t *testing.T) {
		testToFile(t, tag, expected)
	})

	tagToIgnore := tag
	for tagToIgnore == tag {
		tagToIgnore = genTag()
	}

	if err := logger.InfoTf(tagToIgnore, "integer: NaN"); err != nil {
		t.Fatal(err)
	}

	t.Run("LogListenerIgnoringTag", func(t *testing.T) {
		testIgnoringTag(t, tag, tagToIgnore, expected)
	})

	t.Run("LogListenerListingAndIgnoringTag", func(t *testing.T) {
		testListingAndIgnoringTag(t, tag, tagToIgnore, expected)
	})
}

func genTag() string {
	var max big.Int
	max.SetInt64(10000)
	r, err := rand.Int(rand.Reader, &max)
	if err != nil {
		log.Fatal(err)
	}
	return fmt.Sprintf("logger_test_%d", r)
}

// testToStdout runs log_listener to listen for the given tag and to write its
// output to stdout. The stdout buffer is then checked for the expected string.
func testToStdout(t *testing.T, tag, expected string) {
	cmd := exec.Command(loglistener, "--tag", tag)
	var stdout bytes.Buffer
	cmd.Stdout = &stdout
	err := cmd.Start()
	if err != nil {
		log.Fatal(err)
	}
	defer cmd.Process.Kill()

	res := tryWithBackoff(t, func() bool {
		return strings.HasSuffix(stdout.String(), expected)
	})

	if !res {
		t.Fatalf("expected suffix: %q, got: %q", expected, stdout.String())
	}
}

// testToFile runs log_listener to listen for the given tag and to write its
// output into a temporary file. The temporary file is then checked for the
// expected string.
func testToFile(t *testing.T, tag, expected string) {
	tmpfile, err := ioutil.TempFile("", "logger-test")
	if err != nil {
		t.Fatal(err)
	}
	tmpfile.Close()
	defer os.Remove(tmpfile.Name())

	cmd := exec.Command(loglistener, "--tag", tag, "--file", tmpfile.Name())
	err = cmd.Start()
	if err != nil {
		log.Fatal(err)
	}
	defer cmd.Process.Kill()

	var fileout []byte
	res := tryWithBackoff(t, func() bool {
		fileout, err = ioutil.ReadFile(tmpfile.Name())
		if err != nil {
			t.Fatal(err)
		}
		return strings.HasSuffix(string(fileout), expected)
	})

	if !res {
		t.Fatalf("expected suffix: %q, got: %q", expected, string(fileout))
	}
}

// tryWithBackoff calls f periodicaly until it returns true
func tryWithBackoff(t *testing.T, f func() bool) bool {
	step_sleep := 10    // in ms
	total_sleep := 5000 // in ms
	tries := total_sleep / step_sleep
	for i := 0; i < tries; i++ {
		if f() {
			return true
		}
		time.Sleep(time.Duration(step_sleep) * time.Millisecond)
	}

	return false
}

// testIgnoringTag runs log_listener configured to listen for `tag` and ignore
// `tagToIgnore`. The last log containing `tag` and not `tagToIgnore` is then
// compared against `expected`.
func testIgnoringTag(t *testing.T, tag, tagToIgnore, expected string) {
	cmd := exec.Command(loglistener, "--tag", tag, "--ignore-tag", tagToIgnore)
	var stdout bytes.Buffer
	cmd.Stdout = &stdout
	err := cmd.Start()
	if err != nil {
		log.Fatal(err)
	}
	defer cmd.Process.Kill()

	res := tryWithBackoff(t, func() bool {
		return strings.HasSuffix(stdout.String(), expected)
	})

	if !res {
		t.Fatalf("expected suffix: %q, got: %q", expected, stdout.String())
	}
}

// testListingAndIgnoringTag runs log_listener configured to listen for `tag`
// AND `tagToIgnore`, and to ignore `tagToIgnore`. The last log containing `tag`
// and not `tagToIgnore` is then compared against `expected` (the same behavior
// as in testIgnoringTag)
func testListingAndIgnoringTag(t *testing.T, tag, tagToIgnore, expected string) {
	cmd := exec.Command(loglistener, "--tag", tag, "--tag", tagToIgnore, "--ignore-tag", tagToIgnore)
	var stdout bytes.Buffer
	cmd.Stdout = &stdout
	err := cmd.Start()
	if err != nil {
		log.Fatal(err)
	}
	defer cmd.Process.Kill()

	res := tryWithBackoff(t, func() bool {
		return strings.HasSuffix(stdout.String(), expected)
	})

	if !res {
		t.Fatalf("expected suffix: %q, got: %q", expected, stdout.String())
	}
}