Merge pull request #617 from bricelalu/feat-logger-add-clean-mode

feat(log): add "raw" mode

10 files changed, 157 insertions, 15 deletions

diff --git a/CHANGELOG.md b/CHANGELOG.md
index d652e1d8..f014a692 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -1,9 +1,13 @@
 CHANGELOG
 =========
 
-v2.1.0 (06.04.2021)
+v2.0.4 (06.04.2021)
 -------------------
 
+## 🔥 New:
+
+- 📜 Add a new `raw` mode for the `logger` plugin to keep the stderr log message of the worker unmodified (logger severity level should be at least `INFO`).
+
 ## 🩹 Fixes:
 
 - 🐛 Fix: bug with the temporal worker which does not follow general graceful shutdown period.
diff --git a/go.mod b/go.mod
index 1a5263fb..0e6c7079 100644
--- a/go.mod
+++ b/go.mod
@@ -15,6 +15,7 @@ require (
 	github.com/golang/mock v1.4.4
 	github.com/hashicorp/go-multierror v1.1.1
 	github.com/json-iterator/go v1.1.10
+	github.com/kami-zh/go-capturer v0.0.0-20171211120116-e492ea43421d
 	github.com/olekukonko/tablewriter v0.0.5
 	github.com/prometheus/client_golang v1.10.0
 	github.com/shirou/gopsutil v3.21.3+incompatible
diff --git a/go.sum b/go.sum
index a015f236..e6d7df35 100644
--- a/go.sum
+++ b/go.sum
@@ -220,6 +220,9 @@ github.com/jtolds/gls v4.20.0+incompatible h1:xdiiI2gbIgH/gLH7ADydsJ1uDOEzR8yvV7
 github.com/jtolds/gls v4.20.0+incompatible/go.mod h1:QJZ7F/aHp+rZTRtaJ1ow/lLfFfVYBRgL+9YlvaHOwJU=
 github.com/julienschmidt/httprouter v1.2.0/go.mod h1:SYymIcj16QtmaHHD7aYtjjsJG7VTCxuUUipMqKk8s4w=
 github.com/julienschmidt/httprouter v1.3.0/go.mod h1:JR6WtHb+2LUe8TCKY3cZOxFyyO8IZAc4RVcycCCAKdM=
+github.com/kami-zh/go-capturer v0.0.0-20171211120116-e492ea43421d h1:cVtBfNW5XTHiKQe7jDaDBSh/EVM4XLPutLAGboIXuM0=
+github.com/kami-zh/go-capturer v0.0.0-20171211120116-e492ea43421d/go.mod h1:P2viExyCEfeWGU259JnaQ34Inuec4R38JCyBx2edgD0=
+github.com/kisielk/errcheck v1.1.0 h1:ZqfnKyx9KGpRcW04j5nnPDgRgoXUeLh2YFBeFzphcA0=
 github.com/kisielk/errcheck v1.1.0/go.mod h1:EZBBE59ingxPouuu3KfxchcWSUPOHkagtvWXihfKN4Q=
 github.com/kisielk/gotool v1.0.0/go.mod h1:XhKaO+MFFWcvkIS/tQcRk01m1F5IRFswLeQ+oQHNcck=
 github.com/klauspost/compress v1.10.7 h1:7rix8v8GpI3ZBb0nSozFRgbtXKv+hOe+qfEpZqybrAg=
diff --git a/plugins/logger/config.go b/plugins/logger/config.go
index 52594bc4..eee5fb71 100644
--- a/plugins/logger/config.go
+++ b/plugins/logger/config.go
@@ -50,6 +50,16 @@ func (cfg *Config) BuildLogger() (*zap.Logger, error) {
 		zCfg = zap.NewProductionConfig()
 	case "development":
 		zCfg = zap.NewDevelopmentConfig()
+	case "raw":
+		zCfg = zap.Config{
+			Level:    zap.NewAtomicLevelAt(zap.InfoLevel),
+			Encoding: "console",
+			EncoderConfig: zapcore.EncoderConfig{
+				MessageKey: "message",
+			},
+			OutputPaths:      []string{"stderr"},
+			ErrorOutputPaths: []string{"stderr"},
+		}
 	default:
 		zCfg = zap.Config{
 			Level:    zap.NewAtomicLevelAt(zap.DebugLevel),
diff --git a/plugins/server/plugin.go b/plugins/server/plugin.go
index f708b15e..c3496ae7 100644
--- a/plugins/server/plugin.go
+++ b/plugins/server/plugin.go
@@ -6,6 +6,7 @@ import (
 	"os"
 	"os/exec"
 	"strings"
+	"unsafe"
 
 	"github.com/spiral/errors"
 	"github.com/spiral/roadrunner/v2/pkg/transport"
@@ -234,10 +235,10 @@ func (server *Plugin) collectEvents(event interface{}) {
 		case events.EventWorkerError:
 			server.log.Error(strings.TrimRight(we.Payload.(error).Error(), " \n\t"))
 		case events.EventWorkerLog:
-			server.log.Debug(strings.TrimRight(string(we.Payload.([]byte)), " \n\t"))
+			server.log.Debug(strings.TrimRight(toString(we.Payload.([]byte)), " \n\t"))
+			// stderr event is INFO level
 		case events.EventWorkerStderr:
-			// TODO unsafe byte to string convert
-			server.log.Debug(strings.TrimRight(string(we.Payload.([]byte)), " \n\t"))
+			server.log.Info(strings.TrimRight(toString(we.Payload.([]byte)), " \n\t"))
 		}
 	}
 }
@@ -248,10 +249,15 @@ func (server *Plugin) collectWorkerLogs(event interface{}) {
 		case events.EventWorkerError:
 			server.log.Error(strings.TrimRight(we.Payload.(error).Error(), " \n\t"))
 		case events.EventWorkerLog:
-			server.log.Debug(strings.TrimRight(string(we.Payload.([]byte)), " \n\t"))
+			server.log.Debug(strings.TrimRight(toString(we.Payload.([]byte)), " \n\t"))
+			// stderr event is INFO level
 		case events.EventWorkerStderr:
-			// TODO unsafe byte to string convert
-			server.log.Debug(strings.TrimRight(string(we.Payload.([]byte)), " \n\t"))
+			server.log.Info(strings.TrimRight(toString(we.Payload.([]byte)), " \n\t"))
 		}
 	}
 }
+
+// unsafe, but lightning fast []byte to string conversion
+func toString(data []byte) string {
+	return *(*string)(unsafe.Pointer(&data))
+}
diff --git a/tests/plugins/http/http_plugin_test.go b/tests/plugins/http/http_plugin_test.go
index cf22a9cd..51c5fda2 100644
--- a/tests/plugins/http/http_plugin_test.go
+++ b/tests/plugins/http/http_plugin_test.go
@@ -1003,21 +1003,22 @@ server:
   env:
     "RR_HTTP": "true"
   relay: "pipes"
-  relayTimeout: "20s"
+  relay_timeout: "20s"
 
 http:
   debug: true
   address: 127.0.0.1:34999
-  maxRequestSize: 1024
+  max_request_size: 1024
   middleware: [ "pluginMiddleware", "pluginMiddleware2" ]
   uploads:
     forbid: [ "" ]
-  trustedSubnets: [ "10.0.0.0/8", "127.0.0.0/8", "172.16.0.0/12", "192.168.0.0/16", "::1/128", "fc00::/7", "fe80::/10" ]
+  trusted_subnets: [ "10.0.0.0/8", "127.0.0.0/8", "172.16.0.0/12", "192.168.0.0/16", "::1/128", "fc00::/7", "fe80::/10" ]
   pool:
-    numWorkers: 2
-    maxJobs: 0
-    allocateTimeout: 60s
-    destroyTimeout: 60s
+    num_workers: 2
+    max_jobs: 0
+    allocate_timeout: 60s
+    destroy_timeout: 60s
+
 logs:
   mode: development
   level: error
@@ -1037,7 +1038,7 @@ logs:
 	mockLogger.EXPECT().Debug("worker destructed", "pid", gomock.Any()).MinTimes(1)
 	mockLogger.EXPECT().Debug("worker constructed", "pid", gomock.Any()).MinTimes(1)
 	mockLogger.EXPECT().Debug("201 GET http://localhost:34999/?hello=world", "remote", "127.0.0.1", "elapsed", gomock.Any()).MinTimes(1)
-	mockLogger.EXPECT().Debug("WORLD", "pid", gomock.Any()).MinTimes(1)
+	mockLogger.EXPECT().Info("WORLD").MinTimes(1)
 	mockLogger.EXPECT().Debug("worker event received", "event", events.EventWorkerLog, "worker state", gomock.Any()).MinTimes(1)
 	mockLogger.EXPECT().Error(gomock.Any(), gomock.Any(), gomock.Any()).AnyTimes() // placeholder for the workerlogerror
 
diff --git a/tests/plugins/logger/configs/.rr-raw-mode.yaml b/tests/plugins/logger/configs/.rr-raw-mode.yaml
new file mode 100644
index 00000000..fba25945
--- /dev/null
+++ b/tests/plugins/logger/configs/.rr-raw-mode.yaml
@@ -0,0 +1,15 @@
+server:
+  command: "php ../../raw-error.php"
+  relay: "pipes"
+
+http:
+  address: 127.0.0.1:34999
+  max_requestSize: 1024
+  pool:
+    num_workers: 1
+    max_jobs: 0
+    allocate_timeout: 10s
+    destroy_timeout: 10s
+
+logs:
+  mode: raw
diff --git a/tests/plugins/logger/logger_test.go b/tests/plugins/logger/logger_test.go
index 7f378026..d2877781 100644
--- a/tests/plugins/logger/logger_test.go
+++ b/tests/plugins/logger/logger_test.go
@@ -4,14 +4,17 @@ import (
 	"os"
 	"os/signal"
 	"sync"
+	"syscall"
 	"testing"
 
+	"github.com/golang/mock/gomock"
 	endure "github.com/spiral/endure/pkg/container"
 	"github.com/spiral/roadrunner/v2/plugins/config"
 	"github.com/spiral/roadrunner/v2/plugins/http"
 	"github.com/spiral/roadrunner/v2/plugins/logger"
 	"github.com/spiral/roadrunner/v2/plugins/rpc"
 	"github.com/spiral/roadrunner/v2/plugins/server"
+	"github.com/spiral/roadrunner/v2/tests/mocks"
 	"github.com/stretchr/testify/assert"
 )
 
@@ -74,6 +77,77 @@ func TestLogger(t *testing.T) {
 	wg.Wait()
 }
 
+func TestLoggerRawErr(t *testing.T) {
+	cont, err := endure.NewContainer(nil, endure.SetLogLevel(endure.ErrorLevel))
+	assert.NoError(t, err)
+
+	// config plugin
+	cfg := &config.Viper{}
+	cfg.Path = "configs/.rr-raw-mode.yaml"
+	cfg.Prefix = "rr"
+
+	controller := gomock.NewController(t)
+	mockLogger := mocks.NewMockLogger(controller)
+
+	mockLogger.EXPECT().Debug("worker destructed", "pid", gomock.Any()).MinTimes(1)
+	mockLogger.EXPECT().Info("{\"field\": \"value\"}").MinTimes(1)
+	mockLogger.EXPECT().Debug("worker constructed", "pid", gomock.Any()).MinTimes(1)
+
+	err = cont.RegisterAll(
+		cfg,
+		mockLogger,
+		&server.Plugin{},
+		&http.Plugin{},
+	)
+	assert.NoError(t, err)
+
+	err = cont.Init()
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	ch, err := cont.Serve()
+	assert.NoError(t, err)
+
+	sig := make(chan os.Signal, 1)
+	signal.Notify(sig, os.Interrupt, syscall.SIGINT, syscall.SIGTERM)
+
+	wg := &sync.WaitGroup{}
+	wg.Add(1)
+
+	stopCh := make(chan struct{}, 1)
+
+	go func() {
+		defer wg.Done()
+		for {
+			select {
+			case e := <-ch:
+				assert.Fail(t, "error", e.Error.Error())
+				err = cont.Stop()
+				if err != nil {
+					assert.FailNow(t, "error", err.Error())
+				}
+			case <-sig:
+				err = cont.Stop()
+				if err != nil {
+					assert.FailNow(t, "error", err.Error())
+				}
+				return
+			case <-stopCh:
+				// timeout
+				err = cont.Stop()
+				if err != nil {
+					assert.FailNow(t, "error", err.Error())
+				}
+				return
+			}
+		}
+	}()
+
+	stopCh <- struct{}{}
+	wg.Wait()
+}
+
 func TestLoggerNoConfig(t *testing.T) {
 	container, err := endure.NewContainer(nil, endure.RetryOnFail(true), endure.SetLogLevel(endure.ErrorLevel))
 	if err != nil {
diff --git a/tests/plugins/logger/plugin.go b/tests/plugins/logger/plugin.go
index 9ddf9ec9..aa62f2b3 100644
--- a/tests/plugins/logger/plugin.go
+++ b/tests/plugins/logger/plugin.go
@@ -1,6 +1,8 @@
 package logger
 
 import (
+	"strings"
+
 	"github.com/spiral/errors"
 	"github.com/spiral/roadrunner/v2/plugins/config"
 	"github.com/spiral/roadrunner/v2/plugins/logger"
@@ -28,6 +30,11 @@ func (p1 *Plugin) Serve() chan error {
 	p1.log.Info("error", "test")
 	p1.log.Debug("error", "test")
 	p1.log.Warn("error", "test")
+
+	// test the `raw` mode
+	messageJSON := []byte(`{"field": "value"}`)
+	p1.log.Debug(strings.TrimRight(string(messageJSON), " \n\t"))
+
 	return errCh
 }
 
diff --git a/tests/raw-error.php b/tests/raw-error.php
new file mode 100644
index 00000000..3caf46c5
--- /dev/null
+++ b/tests/raw-error.php
@@ -0,0 +1,21 @@
+<?php
+/**
+ * @var Goridge\RelayInterface $relay
+ */
+use Spiral\Goridge;
+use Spiral\RoadRunner;
+
+ini_set('display_errors', 'stderr');
+require __DIR__ . "/vendor/autoload.php";
+
+$worker = new RoadRunner\Worker(new Goridge\StreamRelay(STDIN, STDOUT));
+$psr7 = new RoadRunner\Http\PSR7Worker(
+    $worker,
+    new \Nyholm\Psr7\Factory\Psr17Factory(),
+    new \Nyholm\Psr7\Factory\Psr17Factory(),
+    new \Nyholm\Psr7\Factory\Psr17Factory()
+);
+
+error_log('{"field": "value"}');
+
+while ($req = $psr7->waitRequest()) {}