Mattermost-server: [Help Wanted] [MM-10199] Investigate capture of stack traces into Mattermost logs

[esethna]

If you're interested please comment here and come join our "Contributors" community channel on our daily build server, where you can discuss questions with community members and the Mattermost core team. For technical advice or questions, please join our "Developers" community channel.

New contributors please see our Developer's Guide.

---

Notes: Jira ticket

Instead of having to configure monitoring for Stderr output, we should investigate trying to ensure all Stderr (and Stdout?) goes to the logger for easier analysis when unexpected issues arise.

For example, if the server panics the stack trace is printed through Stderr and doesn't show up in the Mattermost logs.

If you have any questions or want to discuss the ticket, feel free to ask @christopher or @lev.brouk in the ~Developers channel on community.mattermost.com

[sandeepsukhani]

Is it okay if I give this a try?

[hanzei]

Sure @sandlis, that would be great!

[sandeepsukhani]

Actually I have done some investigation already.
Is this limited to panics that occur while serving requests?
If so then changing following line from

  Handler: handlers.RecoveryHandler(handlers.RecoveryLogger(&RecoveryLogger{}), handlers.PrintRecoveryStack(true))(handler),

to

Handler: handler

should make it work. Currently the issue is handlers.RecoveryHandler is using debug.PrintStack(), which prints stack to stderr. While default behaviour is printing it to http.Server.ErrorLog, if it is set. We already are setting ErrorLog to mattermost logger.

Here is example stack from log file from my local server with this change and FileJson log setting set to false:

2019-02-27T16:22:24.687+0530    info    http/server.go:1747 http: panic serving 127.0.0.1:46220: dont login
goroutine 3913 [running]:
net/http.(*conn).serve.func1(0xc0015cd4a0)
    /usr/local/go/src/net/http/server.go:1746 +0xd0
panic(0x1214080, 0x16196e0)
    /usr/local/go/src/runtime/panic.go:513 +0x1b9
github.com/mattermost/mattermost-server/app.(*App).DoLogin(0xc00012d500, 0x162db80, 0xc001c9a540, 0xc002a84900, 0xc00232aa00, 0x0, 0x0, 0x0, 0x0)
    /media/sandeep/project/golang/src/github.com/mattermost/mattermost-server/app/login.go:111 +0x39
github.com/mattermost/mattermost-server/api4.login(0xc0028a9410, 0x162db80, 0xc001c9a540, 0xc002a84900)
    /media/sandeep/project/golang/src/github.com/mattermost/mattermost-server/api4/user.go:1150 +0x939
github.com/mattermost/mattermost-server/web.Handler.ServeHTTP(0xc001fd3250, 0x14f9540, 0x0, 0x162db80, 0xc001c9a540, 0xc002a84900)
    /media/sandeep/project/golang/src/github.com/mattermost/mattermost-server/web/handlers.go:163 +0x124c
github.com/mattermost/mattermost-server/vendor/github.com/gorilla/mux.(*Router).ServeHTTP(0xc000292cb0, 0x162db80, 0xc001c9a540, 0xc002a84900)
    /media/sandeep/project/golang/src/github.com/mattermost/mattermost-server/vendor/github.com/gorilla/mux/mux.go:162 +0xf1
net/http.serverHandler.ServeHTTP(0xc001e22dd0, 0x162db80, 0xc001c9a540, 0xc0013b6300)
    /usr/local/go/src/net/http/server.go:2741 +0xab
net/http.(*conn).serve(0xc0015cd4a0, 0x162ec40, 0xc00173ad80)
    /usr/local/go/src/net/http/server.go:1847 +0x646
created by net/http.(*Server).Serve
    /usr/local/go/src/net/http/server.go:2851 +0x2f5    {"source": "httpserver"}

[sandeepsukhani]

If we want to do this for any panic that occurs on the server be it while serving requests or from running jobs, we will have to redirect writes to stderr to some other file. As mentioned here, to do this we'll have to use syscall.Dup and use a package like this to follow new changes and keep pushing it to mlog.

[crspeller]

@sandlis Thanks for taking a look. The handler fix is a great start, feel free to put in the PR for that.
We would want panics anywhere to be redirected as well. The Dup to a file thing seems inconvenient but could work. Is it possible to just have some recover code that copies the panic to mlog? Or would that not cover all cases?

[sandeepsukhani]

Recover code would work but what all piece of code would we cover? It can be huge if scope is not limited. We can miss some places or someone making new changes might miss it.

[crspeller]

Ya we would have to cover every go routine so that would probably not be great.

[levb]

After chatting with Jesse, I understand why we are doing this, and I too amsupportive of the (1-liner?) to fix the http request panic logging. 0/5 we should still be encouraging customers to capture the standard output streams when running the server process, it just seems the right discipline.

[sandeepsukhani]

I have sent a WIP PR with handler fix. Will do changes for logging errors and stack traces from stderr to mlog, once we get to a conclusion. As of now using Dup seems to be the only feasible way to do it.

[jasonblais]

Thanks @sandlis!