[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

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

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

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 {