From fdf9c3e218f33d8355209f54aa36853a027c2650 Mon Sep 17 00:00:00 2001
From: Sandeep Sukhani <sandeep.d.sukhani@gmail.com>
Date: Mon, 11 Mar 2019 22:32:34 +0530
Subject: [PATCH] [MM-10199] Capture of stack traces into Mattermost logs
 (#10379)

* [MM-10199] Printing stack traces from http handlers panics in mattermost logs

Previously recovery handlers from gorilla mux was used, which was printing stack traces from panics in stderr
Removing it should print stack traces into logger passed to http.Server, which as of now is created from mlog

Refer #10351

* Logging errors from http server at error level instead of info level
Added test for verifying whether panic gets logged in server logger

* Fixed failing test due to tls error

* Closing temp file for panic log before removing and checking errors for closure and removal

* Added regular log line in panic handler for TestPanicLog to check whether it gets logged
---
 app/server.go      | 19 +++++-------
 app/server_test.go | 77 ++++++++++++++++++++++++++++++++++++++++++++++
 mlog/log.go        |  5 +++
 3 files changed, 90 insertions(+), 11 deletions(-)

diff --git a/app/server.go b/app/server.go
index 93b2ac9a58..9e0a5cb412 100644
--- a/app/server.go
+++ b/app/server.go
@@ -17,7 +17,6 @@ import (
 	"sync/atomic"
 	"time"
 
-	"github.com/gorilla/handlers"
 	"github.com/gorilla/mux"
 	"github.com/pkg/errors"
 	"github.com/rs/cors"
@@ -371,14 +370,6 @@ var corsAllowedMethods = []string{
 	"DELETE",
 }
 
-type RecoveryLogger struct {
-}
-
-func (rl *RecoveryLogger) Println(i ...interface{}) {
-	mlog.Error("Please check the std error output for the stack trace")
-	mlog.Error(fmt.Sprint(i...))
-}
-
 // golang.org/x/crypto/acme/autocert/autocert.go
 func handleHTTPRedirect(w http.ResponseWriter, r *http.Request) {
 	if r.Method != "GET" && r.Method != "HEAD" {
@@ -436,11 +427,17 @@ func (s *Server) Start() error {
 		handler = rateLimiter.RateLimitHandler(handler)
 	}
 
+	// Creating a logger for logging errors from http.Server at error level
+	errStdLog, err := s.Log.StdLogAt(mlog.LevelError, mlog.String("source", "httpserver"))
+	if err != nil {
+		return err
+	}
+
 	s.Server = &http.Server{
-		Handler:      handlers.RecoveryHandler(handlers.RecoveryLogger(&RecoveryLogger{}), handlers.PrintRecoveryStack(true))(handler),
+		Handler:      handler,
 		ReadTimeout:  time.Duration(*s.Config().ServiceSettings.ReadTimeout) * time.Second,
 		WriteTimeout: time.Duration(*s.Config().ServiceSettings.WriteTimeout) * time.Second,
-		ErrorLog:     s.Log.StdLog(mlog.String("source", "httpserver")),
+		ErrorLog:     errStdLog,
 	}
 
 	addr := *s.Config().ServiceSettings.ListenAddress
diff --git a/app/server_test.go b/app/server_test.go
index 4ab34b7a31..6012cb0af9 100644
--- a/app/server_test.go
+++ b/app/server_test.go
@@ -4,9 +4,13 @@
 package app
 
 import (
+	"bufio"
 	"crypto/tls"
+	"github.com/mattermost/mattermost-server/mlog"
+	"io/ioutil"
 	"net"
 	"net/http"
+	"os"
 	"path"
 	"strconv"
 	"strings"
@@ -207,3 +211,76 @@ func checkEndpoint(t *testing.T, client *http.Client, url string, expectedStatus
 
 	return nil
 }
+
+func TestPanicLog(t *testing.T) {
+	// Creating a temp file to collect logs
+	tmpfile, err := ioutil.TempFile("", "mlog")
+	if err != nil {
+		require.NoError(t, err)
+	}
+
+	defer func() {
+		require.NoError(t, tmpfile.Close())
+		require.NoError(t, os.Remove(tmpfile.Name()))
+	}()
+
+	// Creating logger to log to console and temp file
+	logger := mlog.NewLogger(&mlog.LoggerConfiguration{
+		EnableConsole: true,
+		ConsoleJson:   true,
+		EnableFile:    true,
+		FileLocation:  tmpfile.Name(),
+		FileLevel: mlog.LevelInfo,
+	})
+
+	// Creating a server with logger
+	s, err := NewServer(SetLogger(logger))
+	require.NoError(t, err)
+
+	// Route for just panicing
+	s.Router.HandleFunc("/panic", func(writer http.ResponseWriter, request *http.Request) {
+		s.Log.Info("inside panic handler")
+		panic("log this panic")
+	})
+
+	s.UpdateConfig(func(cfg *model.Config) { *cfg.ServiceSettings.ListenAddress = ":0" })
+	serverErr := s.Start()
+	require.NoError(t, serverErr)
+
+	// Calling panic route
+	tr := &http.Transport{
+		TLSClientConfig: &tls.Config{InsecureSkipVerify: true},
+	}
+
+	client := &http.Client{Transport: tr}
+	client.Get("https://localhost:" + strconv.Itoa(s.ListenAddr.Port) + "/panic")
+
+	err = s.Shutdown()
+	require.NoError(t, err)
+
+	// Checking whether panic was logged
+	var panicLogged = false
+	var infoLogged = false
+
+	_, err = tmpfile.Seek(0, 0)
+	require.NoError(t, err)
+
+	scanner := bufio.NewScanner(tmpfile)
+	for scanner.Scan() {
+		if !infoLogged && strings.Contains(scanner.Text(), "inside panic handler") {
+			infoLogged = true
+		}
+		if strings.Contains(scanner.Text(), "log this panic") {
+			panicLogged = true
+			break
+		}
+	}
+
+	if !infoLogged {
+		t.Error("Info log line was supposed to be logged")
+	}
+
+	if !panicLogged {
+		t.Error("Panic was supposed to be logged")
+	}
+}
diff --git a/mlog/log.go b/mlog/log.go
index dd35a30750..a2945046fe 100644
--- a/mlog/log.go
+++ b/mlog/log.go
@@ -127,6 +127,11 @@ func (l *Logger) StdLog(fields ...Field) *log.Logger {
 	return zap.NewStdLog(l.With(fields...).zap.WithOptions(getStdLogOption()))
 }
 
+// StdLogAt returns *log.Logger which writes to supplied zap logger at required level.
+func (l *Logger) StdLogAt(level string, fields ...Field) (*log.Logger, error) {
+	return zap.NewStdLogAt(l.With(fields...).zap.WithOptions(getStdLogOption()), getZapLevel(level))
+}
+
 // StdLogWriter returns a writer that can be hooked up to the output of a golang standard logger
 // anything written will be interpreted as log entries accordingly
 func (l *Logger) StdLogWriter() io.Writer {