- Add ability to print http/https/fcgi to the rr logger under the Info

  level
- Update tests and CHANGELOG

Signed-off-by: Valery Piashchynski <[email protected]>

6 files changed, 72 insertions, 23 deletions

diff --git a/CHANGELOG.md b/CHANGELOG.md
index 3db752fe..152b00e6 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -1,6 +1,11 @@
 CHANGELOG
 =========
 
+v2.0.1 (23.03.2021)
+-------------------
+- 🐛 Fix: Bug with required Root CA certificate for the SSL, not it's optional.
+- 🆕 New: HTTP/FCGI/HTTPS internal logs instead of going to the raw stdout will be displayed in the RR logger at the `Info` log level.
+
 v2.0.1 (09.03.2021)
 -------------------
 - 🐛 Fix: incorrect PHP command validation
diff --git a/plugins/http/plugin.go b/plugins/http/plugin.go
index 59f8a9d7..0686f6b5 100644
--- a/plugins/http/plugin.go
+++ b/plugins/http/plugin.go
@@ -6,6 +6,7 @@ import (
 	"crypto/x509"
 	"fmt"
 	"io/ioutil"
+	"log"
 	"net/http"
 	"net/http/fcgi"
 	"net/url"
@@ -54,6 +55,8 @@ type Plugin struct {
 	// plugins
 	server server.Server
 	log    logger.Logger
+	// stdlog passed to the http/https/fcgi servers to log their internal messages
+	stdLog *log.Logger
 
 	cfg *httpConfig.HTTP `mapstructure:"http"`
 	// middlewares to chain
@@ -73,7 +76,7 @@ type Plugin struct {
 
 // Init must return configure svc and return true if svc hasStatus enabled. Must return error in case of
 // misconfiguration. Services must not be used without proper configuration pushed first.
-func (s *Plugin) Init(cfg config.Configurer, log logger.Logger, server server.Server) error {
+func (s *Plugin) Init(cfg config.Configurer, rrLogger logger.Logger, server server.Server) error {
 	const op = errors.Op("http_plugin_init")
 	if !cfg.Has(PluginName) {
 		return errors.E(op, errors.Disabled)
@@ -89,7 +92,11 @@ func (s *Plugin) Init(cfg config.Configurer, log logger.Logger, server server.Se
 		return errors.E(op, err)
 	}
 
-	s.log = log
+	// rr logger (via plugin)
+	s.log = rrLogger
+	// use time and date in UTC format
+	s.stdLog = log.New(logger.NewStdAdapter(s.log), "http_plugin: ", log.Ldate|log.Ltime|log.LUTC)
+
 	s.mdwr = make(map[string]Middleware)
 
 	if !s.cfg.EnableHTTP() && !s.cfg.EnableTLS() && !s.cfg.EnableFCGI() {
@@ -153,9 +160,9 @@ func (s *Plugin) Serve() chan error {
 
 	if s.cfg.EnableHTTP() {
 		if s.cfg.EnableH2C() {
-			s.http = &http.Server{Handler: h2c.NewHandler(s, &http2.Server{})}
+			s.http = &http.Server{Handler: h2c.NewHandler(s, &http2.Server{}), ErrorLog: s.stdLog}
 		} else {
-			s.http = &http.Server{Handler: s}
+			s.http = &http.Server{Handler: s, ErrorLog: s.stdLog}
 		}
 	}
 
@@ -179,7 +186,7 @@ func (s *Plugin) Serve() chan error {
 	}
 
 	if s.cfg.EnableFCGI() {
-		s.fcgi = &http.Server{Handler: s}
+		s.fcgi = &http.Server{Handler: s, ErrorLog: s.stdLog}
 	}
 
 	// start http, https and fcgi servers if requested in the config
@@ -304,7 +311,7 @@ func (s *Plugin) Stop() error {
 
 // ServeHTTP handles connection using set of middleware and pool PSR-7 server.
 func (s *Plugin) ServeHTTP(w http.ResponseWriter, r *http.Request) {
-	if headerContainsUpgrade(r, s) {
+	if headerContainsUpgrade(r) {
 		http.Error(w, "server does not support upgrade header", http.StatusInternalServerError)
 		return
 	}
@@ -414,11 +421,10 @@ func (s *Plugin) redirect(w http.ResponseWriter, r *http.Request) {
 	http.Redirect(w, r, target.String(), http.StatusTemporaryRedirect)
 }
 
+// https://golang.org/pkg/net/http/#Hijacker
 //go:inline
-func headerContainsUpgrade(r *http.Request, s *Plugin) bool {
+func headerContainsUpgrade(r *http.Request) bool {
 	if _, ok := r.Header["Upgrade"]; ok {
-		// https://golang.org/pkg/net/http/#Hijacker
-		s.log.Error("server does not support Upgrade header")
 		return true
 	}
 	return false
@@ -507,8 +513,9 @@ func (s *Plugin) initSSL() *http.Server {
 	DefaultCipherSuites = append(DefaultCipherSuites, defaultCipherSuitesTLS13...)
 
 	sslServer := &http.Server{
-		Addr:    s.tlsAddr(s.cfg.Address, true),
-		Handler: s,
+		Addr:     s.tlsAddr(s.cfg.Address, true),
+		Handler:  s,
+		ErrorLog: s.stdLog,
 		TLSConfig: &tls.Config{
 			CurvePreferences: []tls.CurveID{
 				tls.CurveP256,
diff --git a/plugins/logger/interface.go b/plugins/logger/interface.go
index 876629a9..5bb2143b 100644
--- a/plugins/logger/interface.go
+++ b/plugins/logger/interface.go
@@ -1,14 +1,12 @@
 package logger
 
-type (
-	// Logger is an general RR log interface
-	Logger interface {
-		Debug(msg string, keyvals ...interface{})
-		Info(msg string, keyvals ...interface{})
-		Warn(msg string, keyvals ...interface{})
-		Error(msg string, keyvals ...interface{})
-	}
-)
+// Logger is an general RR log interface
+type Logger interface {
+	Debug(msg string, keyvals ...interface{})
+	Info(msg string, keyvals ...interface{})
+	Warn(msg string, keyvals ...interface{})
+	Error(msg string, keyvals ...interface{})
+}
 
 // With creates a child logger and adds structured context to it
 type WithLogger interface {
diff --git a/plugins/logger/std_log_adapter.go b/plugins/logger/std_log_adapter.go
new file mode 100644
index 00000000..d9a29451
--- /dev/null
+++ b/plugins/logger/std_log_adapter.go
@@ -0,0 +1,31 @@
+package logger
+
+import (
+	"unsafe"
+)
+
+// StdLogAdapter can be passed to the http.Server or any place which required standard logger to redirect output
+// to the logger plugin
+type StdLogAdapter struct {
+	log Logger
+}
+
+// Write io.Writer interface implementation
+func (s *StdLogAdapter) Write(p []byte) (n int, err error) {
+	s.log.Info("server internal stderr", "message", toString(p))
+	return len(p), nil
+}
+
+// NewStdAdapter constructs StdLogAdapter
+func NewStdAdapter(log Logger) *StdLogAdapter {
+	logAdapter := &StdLogAdapter{
+		log: log,
+	}
+
+	return logAdapter
+}
+
+// unsafe, but lightning fast []byte to string conversion
+func toString(data []byte) string {
+	return *(*string)(unsafe.Pointer(&data))
+}
diff --git a/tests/plugins/http/configs/.rr-h2c.yaml b/tests/plugins/http/configs/.rr-h2c.yaml
index 2061a76b..bd610bb0 100644
--- a/tests/plugins/http/configs/.rr-h2c.yaml
+++ b/tests/plugins/http/configs/.rr-h2c.yaml
@@ -24,5 +24,6 @@ http:
     h2c: true
     maxConcurrentStreams: 128
 logs:
-  mode: development
-  level: error
\ No newline at end of file
+  mode: production
+  level: info
+  encoding: console
\ No newline at end of file
diff --git a/tests/plugins/http/http_plugin_test.go b/tests/plugins/http/http_plugin_test.go
index d55491ea..752bd84e 100644
--- a/tests/plugins/http/http_plugin_test.go
+++ b/tests/plugins/http/http_plugin_test.go
@@ -705,11 +705,18 @@ func TestH2CUpgrade(t *testing.T) {
 		Path:   "configs/.rr-h2c.yaml",
 		Prefix: "rr",
 	}
+	controller := gomock.NewController(t)
+	mockLogger := mocks.NewMockLogger(controller)
+
+	mockLogger.EXPECT().Info("server internal stderr", "message", gomock.Any()).MinTimes(1)
+	mockLogger.EXPECT().Debug("worker destructed", "pid", gomock.Any()).MinTimes(1)
+	mockLogger.EXPECT().Debug("worker constructed", "pid", gomock.Any()).MinTimes(1)
+	mockLogger.EXPECT().Debug("worker event received", "event", events.EventWorkerLog, "worker state", gomock.Any()).MinTimes(1)
 
 	err = cont.RegisterAll(
 		cfg,
 		&rpcPlugin.Plugin{},
-		&logger.ZapLogger{},
+		mockLogger,
 		&server.Plugin{},
 		&httpPlugin.Plugin{},
 	)