hook_test.go

package logrus_rollbar

import (
	"net/http"
	"runtime"
	"strings"
	"sync"
	"testing"

	"github.com/rollbar/rollbar-go"
	"github.com/sirupsen/logrus"
)

type mockSender struct {
	sync.Mutex
	calls []senderParams
}

type senderParams struct {
	severity string
	req      *http.Request
	error    error
	fields   map[string]interface{}
}

func (s *mockSender) RequestError(severity string, req *http.Request, err error, fields map[string]interface{}) {
	s.Lock()
	defer s.Unlock()
	s.calls = append(s.calls, senderParams{severity: severity, req: req, error: err, fields: fields})
}

func (s *mockSender) Error(severity string, err error, fields map[string]interface{}) {
	s.Lock()
	defer s.Unlock()
	s.calls = append(s.calls, senderParams{severity: severity, error: err, fields: fields})
}

func TestHook_Fire(t *testing.T) {
	sender := &mockSender{}
	hook := hook{Sender: sender}
	logger := logrus.New()
	entry := logrus.NewEntry(logger)
	entry.Message = "line of log"

	err := hook.Fire(entry)
	if err != nil {
		t.Errorf("expected nil error, got %v", err)
	}

	if len(sender.calls) != 1 {
		t.Errorf("expected 1 call, got %v", len(sender.calls))
	}

	params := sender.calls[0]
	if params.severity != rollbar.ERR {
		t.Errorf("expected severity error, got %v", params.severity)
	}

	if params.error.Error() != "line of log" {
		t.Errorf("expected '%v' error, got '%v'", entry.Message, params.error.Error())
	}
}

func TestHook_FireWithReq(t *testing.T) {
	sender := &mockSender{}
	hook := hook{Sender: sender}
	logger := logrus.New()
	entry := logrus.NewEntry(logger)
	entry.Data["msg"] = "line of log"

	req, _ := http.NewRequest("GET", "/", nil)
	req.Header.Add("Authorization", "password")
	entry.Data["req"] = req

	err := hook.Fire(entry)
	if err != nil {
		t.Errorf("expected nil error, got '%v'", err)
	}

	params := sender.calls[0]
	if params.req.Header.Get("Authorization") != "" {
		t.Errorf("expected Authorization header to be cleared, got %v", params.req.Header.Get("Authorization"))
	}
}

func TestHook_WithExtraField(t *testing.T) {
	sender := &mockSender{}
	hook := hook{Sender: sender}
	logger := logrus.New()
	entry := logrus.NewEntry(logger)
	entry.Data["msg"] = "line of log"
	entry.Data["extra"] = "extrafield"

	err := hook.Fire(entry)
	if err != nil {
		t.Errorf("expected nil error, got '%v'", err)
	}

	params := sender.calls[0]
	if len(params.fields) != 1 {
		t.Errorf("expected 1 extra field, got %v", len(params.fields))
	}
	extra, ok := params.fields["extra"]
	if !ok {
		t.Errorf("expected extra field string, got %t", params.fields["extra"])
	}
	if extra != "extrafield" {
		t.Errorf("expected 'extrafield' value for extra field, got %v", extra)
	}
}

// Test when a request object is used multiple times in error handling (example multiple goroutine)
// This test case aims at testing race conditions
func TestHook_FireWithReq_Concurrent(t *testing.T) {
	sender := &mockSender{}
	hook := hook{Sender: sender}
	logger := logrus.New()
	req, _ := http.NewRequest("GET", "/", nil)
	req.Header.Add("Authorization", "password")

	// Entries are only created and sent once, it is not safe to send twice the
	// same entry through the hook
	wg := &sync.WaitGroup{}
	wg.Add(2)
	go func() {
		entry := logrus.NewEntry(logger)
		entry.Data["msg"] = "line of log"
		entry.Data["req"] = req

		hook.Fire(entry)
		wg.Done()
	}()
	go func() {
		entry := logrus.NewEntry(logger)
		entry.Data["msg"] = "line of log"
		entry.Data["req"] = req

		hook.Fire(entry)
		wg.Done()
	}()
	wg.Wait()

	if len(sender.calls) != 2 {
		t.Errorf("expected 2 call, got %v", len(sender.calls))
	}
}

// Test that the stack is correctly sent when an errors from github.com/pkg/errors is sent
func TestHook_WithPkgErrors(t *testing.T) {
	sender := &mockSender{}
	hook := hook{Sender: sender}
	logger := logrus.New()
	entry := logrus.NewEntry(logger)
	entry.Data["error"] = errorsFoo()

	err := hook.Fire(entry)
	if err != nil {
		t.Errorf("expected nil error, got '%v'", err)
	}

	if len(sender.calls) != 1 {
		t.Errorf("expected 1 call, got %v", len(sender.calls))
	}

	params := sender.calls[0]
	// github.com/Scalingo/logrus-rollbar.errorsBar
	// 	/home/leo/Projects/Go/src/github.com/Scalingo/logrus-rollbar/hook_pkgerrors_test.go:12
	// github.com/Scalingo/logrus-rollbar.errorsFoo
	// 	/home/leo/Projects/Go/src/github.com/Scalingo/logrus-rollbar/hook_pkgerrors_test.go:8
	// github.com/Scalingo/logrus-rollbar.TestHook_WithPkgErrors
	// 	/home/leo/Projects/Go/src/github.com/Scalingo/logrus-rollbar/hook_test.go:155
	// testing.tRunner
	// 	/opt/go/src/testing/testing.go:657
	// runtime.goexit
	// 	/opt/go/src/runtime/asm_amd64.s:2197
	werr, ok := params.error.(rollbar.CauseStacker)
	if !ok {
		t.Fatalf("%v should be a rollbar.CauseStacker", params.error)
	}
	// We generate the stack here while usually it is generated by the rollbar
	// lib, so we got 4 extra levels of execution when we call Stack() (goexit -> trunner -> trunner -> test)
	stack := werr.Stack()
	if len(stack) != 5 {
		t.Fatalf("expecting a stack of 5 levels, got %v: \n===\n%v", len(stack), stack)
	}

	expectedStack := []runtime.Frame{
		{
			Line:     12,
			Function: "errorsBar",
			File:     "hook_pkgerrors_test.go",
		}, {
			Line:     8,
			Function: "errorsFoo",
			File:     "hook_pkgerrors_test.go",
		}, {
			Line:     154,
			Function: "TestHook_WithPkgErrors",
			File:     "hook_test.go",
		}, {
			Function: "tRunner",
			File:     "testing.go",
		}, {
			Function: "goexit",
			File:     "asm_amd64.s",
		},
	}

	for i, _ := range expectedStack {
		if stack[i].Function != expectedStack[i].Function {
			t.Errorf("expected method %v, got %v", expectedStack[i].Function, stack[i].Function)
		}
		if !strings.HasSuffix(stack[i].File, expectedStack[i].File) {
			t.Errorf("expected filename %v, got %v", expectedStack[i].File, stack[i].File)
		}
		if expectedStack[i].Line != 0 && stack[i].Line != expectedStack[i].Line {
			t.Errorf("expected line %v, got %v", expectedStack[i].Line, stack[i].Line)
		}
	}
}