Structured logging

_tests/integration/log_format_test.go

@@ -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
+}

_tests/integration/log_format_test_bitrise.yml

@@ -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
+    - script@1.1:
+        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

analytics/legacy.go

@@ -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
+	}
+
+}

analytics/logger.go

@@ -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
+}

analytics/tracker.go

@@ -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 (
@@ -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)

bitrise.yml

@@ -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

bitrise/dependencies.go

@@ -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"
@@ -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))
 		}
 	}
 
@@ -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
 	}
@@ -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")