Skip to content

Commit

Permalink
Structured logging (#818)
Browse files Browse the repository at this point in the history
* Update dependency

* Use new logger

* Add temp version number

* Update go-utils/advancedlog

* Update go-utils/advancedlog

* Code cleanup

* Migrate remaining go-utils/log usages to advancedlog

* Migrate remaining fmt usages to advancedlog

* Code cleanup

* Update version.go

* Test json and console log compatibility

* Update log_format_test_bitrise.yml

* Update dependency

* Use new logger

* Update go-utils/advancedlog

* Update go-utils/advancedlog

* Code cleanup

* Migrate remaining fmt usages to advancedlog

* Code cleanup

* Rebase fixes

* Pull latest go-utils/v2

* Fix rebase

* Fix rebase

* Fix rebase

* Move advancedlog package to bitrise

* Rename advancedlog package to log

* Update paths.go

* Hangdetector log with timestamp

* Add producer id to step logs

* Code cleanup

* Console logger tests

* PR fixes

* Constructor for utilsLogAdapter

* Introduce new LoggerOpts

* Update run_test.go

* Remove configs.LoggerType

* PR fixes

Co-authored-by: Szabolcs Toth <[email protected]>
  • Loading branch information
godrei and tothszabi authored Oct 12, 2022
1 parent a05b4e0 commit 92bff8c
Show file tree
Hide file tree
Showing 79 changed files with 2,029 additions and 428 deletions.
115 changes: 115 additions & 0 deletions _tests/integration/log_format_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,115 @@
package integration

import (
"bytes"
"encoding/json"
"os/exec"
"regexp"
"testing"

"github.com/stretchr/testify/require"
)

func TestConsoleLogCanBeRestoredFromJSONLog(t *testing.T) {
consoleLog := createConsoleLog(t)
jsonLog := createJSONleLog(t)
convertedConsoleLog := restoreConsoleLog(t, jsonLog)
require.Equal(t, replaceVariableParts(consoleLog), replaceVariableParts(convertedConsoleLog))
}

func createConsoleLog(t *testing.T) string {
execCmd := exec.Command(binPath(), "setup")
outBytes, err := execCmd.CombinedOutput()
require.NoError(t, err, string(outBytes))

cmd := exec.Command(binPath(), "run", "fail_test", "--config", "log_format_test_bitrise.yml")
out, err := cmd.CombinedOutput()
require.EqualError(t, err, "exit status 1")
return string(out)
}

func createJSONleLog(t *testing.T) []byte {
execCmd := exec.Command(binPath(), "setup")
outBytes, err := execCmd.CombinedOutput()
require.NoError(t, err, string(outBytes))

cmd := exec.Command(binPath(), "run", "fail_test", "--config", "log_format_test_bitrise.yml", "--output-format", "json")
out, err := cmd.CombinedOutput()
require.EqualError(t, err, "exit status 1")
return out
}

func restoreConsoleLog(t *testing.T, log []byte) string {
type Log struct {
Message string `json:"message"`
Level string `json:"level"`
}

var consoleLog string
lines := bytes.Split(log, []byte("\n"))
for _, line := range lines {
if string(line) == "" {
continue
}
var log Log
err := json.Unmarshal(line, &log)
require.NoError(t, err, string(line))
consoleLog += createLogMsg(log.Level, log.Message)
}
return consoleLog
}

var levelToANSIColorCode = map[level]ansiColorCode{
errorLevel: redCode,
warnLevel: yellowCode,
infoLevel: blueCode,
doneLevel: greenCode,
debugLevel: magentaCode,
}

func createLogMsg(lvl string, message string) string {
color := levelToANSIColorCode[level(lvl)]
if color != "" {
return addColor(color, message)
}
return message
}

func addColor(color ansiColorCode, msg string) string {
return string(color) + msg + string(resetCode)
}

type level string

const (
errorLevel level = "error"
warnLevel level = "warn"
infoLevel level = "info"
doneLevel level = "done"
normalLevel level = "normal"
debugLevel level = "debug"
)

type ansiColorCode string

const (
redCode ansiColorCode = "\x1b[31;1m"
yellowCode ansiColorCode = "\x1b[33;1m"
blueCode ansiColorCode = "\x1b[34;1m"
greenCode ansiColorCode = "\x1b[32;1m"
magentaCode ansiColorCode = "\x1b[35;1m"
resetCode ansiColorCode = "\x1b[0m"
)

func replaceVariableParts(line string) string {
timeRegexp := regexp.MustCompile(`(\| time: .+\|)`)
line = timeRegexp.ReplaceAllString(line, "[REPLACED]")

runTimeRegexp := regexp.MustCompile(`(\| .+ sec \|)`)
line = runTimeRegexp.ReplaceAllString(line, "[REPLACED]")

totalRunTimeRegexp := regexp.MustCompile(`(\| Total runtime: .+ \|)`)
line = totalRunTimeRegexp.ReplaceAllString(line, "[REPLACED]")

return line
}
36 changes: 36 additions & 0 deletions _tests/integration/log_format_test_bitrise.yml
Original file line number Diff line number Diff line change
@@ -0,0 +1,36 @@
format_version: "11"
default_step_lib_source: https://github.com/bitrise-io/bitrise-steplib.git
project_type: other

workflows:
fail_test:
title: Fails
description: Workflow will fail
steps:
- script:
title: Success
inputs:
- content: |-
set -ex
exit 0
- [email protected]:
title: Fail wit exit code 2
inputs:
- content: |-
set -ex
exit 2
- git::https://github.com/bitrise-steplib/steps-script.git@master:
title: Skippable fail with exit code 2
is_always_run: true
is_skippable: true
inputs:
- content: |-
set -ex
exit 2
- script:
title: Skipping success
is_always_run: false
inputs:
- content: |-
set -ex
exit 0
69 changes: 69 additions & 0 deletions analytics/legacy.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,69 @@
package analytics

import (
"bytes"
"context"
"encoding/json"
"fmt"
"net/http"
"time"

"github.com/bitrise-io/bitrise/log"
)

var (
analyticsServerURL = "https://bitrise-step-analytics.herokuapp.com"
httpClient = http.Client{
Timeout: time.Second * 5,
}
)

// LogMessage sends the log message to the configured analytics server
func LogMessage(logLevel string, stepID string, tag string, data map[string]interface{}, format string, v ...interface{}) {
// Entry represents a line in a log
e := struct {
LogLevel string `json:"log_level"`
Message string `json:"message"`
Data map[string]interface{} `json:"data"`
}{
Message: fmt.Sprintf(format, v...),
LogLevel: logLevel,
}

e.Data = make(map[string]interface{})
for k, v := range data {
e.Data[k] = v
}

if v, ok := e.Data["step_id"]; ok {
log.Printf("internal logger: data.step_id (%s) will be overriden with (%s) ", v, stepID)
}
if v, ok := e.Data["tag"]; ok {
log.Printf("internal logger: data.tag (%s) will be overriden with (%s) ", v, tag)
}

e.Data["step_id"] = stepID
e.Data["tag"] = tag

var b bytes.Buffer
if err := json.NewEncoder(&b).Encode(e); err != nil {
return
}

ctx, cancel := context.WithTimeout(context.Background(), 3*time.Second)
defer cancel()

req, err := http.NewRequest(http.MethodPost, analyticsServerURL+"/logs", &b)
if err != nil {
// deliberately not writing into users log
return
}
req = req.WithContext(ctx)
req.Header.Add("Content-Type", "application/json")

if _, err := httpClient.Do(req); err != nil {
// deliberately not writing into users log
return
}

}
47 changes: 47 additions & 0 deletions analytics/logger.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,47 @@
package analytics

import (
"github.com/bitrise-io/bitrise/log"
)

// utilsLogAdapter extends the bitrise/log.Logger to meet the go-utils/v2/log.Logger interface.
type utilsLogAdapter struct {
debug bool
log.Logger
}

func newUtilsLogAdapter() utilsLogAdapter {
opts := log.GetGlobalLoggerOpts()
return utilsLogAdapter{
Logger: log.NewLogger(opts),
debug: opts.DebugLogEnabled,
}
}

func (l *utilsLogAdapter) TInfof(format string, v ...interface{}) {
log.Infof(format, v...)
}
func (l *utilsLogAdapter) TWarnf(format string, v ...interface{}) {
log.Warnf(format, v...)
}
func (l *utilsLogAdapter) TPrintf(format string, v ...interface{}) {
log.Printf(format, v...)
}
func (l *utilsLogAdapter) TDonef(format string, v ...interface{}) {
log.Donef(format, v...)
}
func (l *utilsLogAdapter) TDebugf(format string, v ...interface{}) {
if !l.debug {
return
}
log.Debugf(format, v...)
}
func (l *utilsLogAdapter) TErrorf(format string, v ...interface{}) {
log.Errorf(format, v...)
}
func (l *utilsLogAdapter) Println() {
log.Print()
}
func (l *utilsLogAdapter) EnableDebugLog(enable bool) {
l.debug = enable
}
12 changes: 3 additions & 9 deletions analytics/tracker.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,14 +6,11 @@ import (
"os"
"time"

"github.com/sirupsen/logrus"

"github.com/bitrise-io/bitrise/configs"
"github.com/bitrise-io/bitrise/models"
"github.com/bitrise-io/bitrise/version"
"github.com/bitrise-io/go-utils/v2/analytics"
"github.com/bitrise-io/go-utils/v2/env"
"github.com/bitrise-io/go-utils/v2/log"
)

const (
Expand Down Expand Up @@ -122,13 +119,10 @@ func NewDefaultTracker() Tracker {
envRepository := env.NewRepository()
stateChecker := NewStateChecker(envRepository)

// Adapter between logrus and go-utils log package
logger := log.NewLogger()
logger.EnableDebugLog(logrus.GetLevel() == logrus.DebugLevel)

tracker := analytics.NewDefaultSyncTracker(logger)
logger := newUtilsLogAdapter()
tracker := analytics.NewDefaultSyncTracker(&logger)
if stateChecker.UseAsync() {
tracker = analytics.NewDefaultTracker(logger)
tracker = analytics.NewDefaultTracker(&logger)
}

return NewTracker(tracker, envRepository, stateChecker)
Expand Down
16 changes: 12 additions & 4 deletions bitrise.yml
Original file line number Diff line number Diff line change
Expand Up @@ -89,19 +89,27 @@ workflows:
- script:
title: Success
inputs:
- content: exit 0
- content: |-
set -ex
exit 0
- script:
title: Fail wit exit code 2
inputs:
- content: exit 2
- content: |-
set -ex
exit 2
- script:
title: Skippable fail with exit code 2
is_always_run: true
is_skippable: true
inputs:
- content: exit 2
- content: |-
set -ex
exit 2
- script:
title: Skipping success
is_always_run: false
inputs:
- content: exit 0
- content: |-
set -ex
exit 0
10 changes: 5 additions & 5 deletions bitrise/dependencies.go
Original file line number Diff line number Diff line change
Expand Up @@ -7,12 +7,12 @@ import (
"strings"
"time"

"github.com/bitrise-io/bitrise/log"
"github.com/bitrise-io/bitrise/plugins"
"github.com/bitrise-io/bitrise/tools"
"github.com/bitrise-io/bitrise/utils"
"github.com/bitrise-io/go-utils/colorstring"
"github.com/bitrise-io/go-utils/command"
"github.com/bitrise-io/go-utils/log"
"github.com/bitrise-io/go-utils/progress"
"github.com/bitrise-io/go-utils/retry"
"github.com/bitrise-io/go-utils/versions"
Expand Down Expand Up @@ -88,7 +88,7 @@ func CheckIsPluginInstalled(name string, dependency PluginDependency) error {
}

if len(plugin.Description) > 0 {
fmt.Println(removeEmptyNewLines(plugin.Description))
log.Print(removeEmptyNewLines(plugin.Description))
}
}

Expand All @@ -106,12 +106,12 @@ func CheckIsHomebrewInstalled(isFullSetupMode bool) error {

progInstallPth, err := utils.CheckProgramInstalledPath("brew")
if err != nil {
fmt.Println()
log.Print()
log.Warnf("It seems that Homebrew is not installed on your system.")
log.Infof("Homebrew (short: brew) is required in order to be able to auto-install all the bitrise dependencies.")
log.Infof("You should be able to install brew by copying this command and running it in your Terminal:")
log.Infof(brewRubyInstallCmdString)
log.Infof("You can find more information about Homebrew on its official site at:", officialSiteURL)
log.Infof("You can find more information about Homebrew on its official site at: %s", officialSiteURL)
log.Warnf("Once the installation of brew is finished you should call the bitrise setup again.")
return err
}
Expand All @@ -129,7 +129,7 @@ func CheckIsHomebrewInstalled(isFullSetupMode bool) error {
doctorOutput, err = command.RunCommandAndReturnCombinedStdoutAndStderr("brew", "doctor")
})
if err != nil {
fmt.Println("")
log.Print()
log.Warnf("brew doctor returned an error:")
log.Warnf("%s", doctorOutput)
return errors.New("command failed: brew doctor")
Expand Down
Loading

0 comments on commit 92bff8c

Please sign in to comment.