Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

chore: Change to defra errors and handle errors stacktrace #794

Merged
merged 5 commits into from
Sep 16, 2022

Conversation

fredcarle
Copy link
Collaborator

Relevant issue(s)

Resolves #750
Resolves #751

Description

This PR moves our error handling from the standard library errors package to our own errors package. It also removes the logger stacktrace default which logs the stacktrace at the line of logging and introduces stacktrace logging from the creation of the error.

Tasks

  • I made sure the code is well commented, particularly hard-to-understand areas.
  • I made sure the repository-held documentation is changed accordingly.
  • I made sure the pull request title adheres to the conventional commit style (the subset used in the project can be found in tools/configs/chglog/config.yml).
  • I made sure to discuss its limitations such as threats to validity, vulnerability to mistake and misuse, robustness to invalidation of assumptions, resource requirements, ...

How has this been tested?

unit tests

Specify the platform(s) on which this was tested:

  • MacOS

@fredcarle fredcarle added area/errors Related to the internal management or design of our error handling system area/logging Related to the logging/logger system action/no-benchmark Skips the action that runs the benchmark. labels Sep 14, 2022
@fredcarle fredcarle added this to the DefraDB v0.3.1 milestone Sep 14, 2022
@fredcarle fredcarle requested a review from a team September 14, 2022 00:07
@fredcarle fredcarle self-assigned this Sep 14, 2022
@fredcarle fredcarle changed the title chore: Change from std errors to defra errors and handle errors stacktrace. chore: Change to defra errors and handle errors stacktrace. Sep 14, 2022
@fredcarle fredcarle changed the title chore: Change to defra errors and handle errors stacktrace. chore: Change to defra errors and handle errors stacktrace Sep 14, 2022
Copy link
Contributor

@AndrewSisley AndrewSisley left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, thanks :)

@@ -102,7 +103,8 @@ func TestLogWritesFatalMessageWithStackTraceToLogAndKillsProcessGivenStackTraceE
assert.Equal(t, logMessage, logLines[0]["msg"])
assert.Equal(t, "FATAL", logLines[0]["level"])
assert.Equal(t, "TestLogName", logLines[0]["logger"])
assert.Contains(t, logLines[0], "stacktrace")
// no stacktrace will be present since no error was sent to the logger.
assert.NotContains(t, logLines[0], "stacktrace")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

praise: Thanks :)

Copy link
Member

@shahzadlone shahzadlone left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great stuff!

@orpheuslummis
Copy link
Contributor

orpheuslummis commented Sep 14, 2022

when logging an error, it includes a stacktrace in the ErrorVerbose even when configured not to include one.

examples, using screenshots because github doesn't wrap oneliners:

using an error i've added in http api module:
Screen Shot 2022-09-14 at 16 45 13

using an error i've added in http api module, configuring defradb to log stacktrace too:
Screen Shot 2022-09-14 at 16 45 06

additionally, it seems it'd be nicer if the stacktrace would be displayed properly (rendering the \n etc)

@fredcarle
Copy link
Collaborator Author

@orpheuslummis that's a different thing. The HTTP API has it's own stacktrace handling from how I had implemented it. I'll open an issue to change it after this is merged. Also the formatting isn't taken into account with the logger. Formatting would be taken into account with a log analysis UI though.

@orpheuslummis
Copy link
Contributor

orpheuslummis commented Sep 15, 2022

noticing: one thing that puzzles me is that the stacktraces now includes asm exit code, whereas i'm pretty sure it didn't before

/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/proc.go:250 (0x104ce6cf0)
        main: fn()
/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/asm_arm64.s:1270 (0x104d15634)
        goexit: MOVD    R0, R0  // NOP

@orpheuslummis
Copy link
Contributor

orpheuslummis commented Sep 15, 2022

issue: FeedbackErrorE includes twice a stacktrace KV when enabling stacktrace in config.

e.g. log.FeedbackErrorE(cmd.Context(), "OK", errors.New("OK")) leading to

2022-09-15T11:26:40.712-0500, ERROR, defra.cli, OK, {"stacktrace": "OK. Stack: /Users/o/dev/defradb/cli/ping.go:29 (0x105676845)\n\tglob..func7: log.FeedbackErrorE(cmd.Context(), \"OK\", errors.New(\"OK\"))\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:856 (0x104b25b84)\n\t(*Command).execute: if err := c.RunE(c, argWoFlags); err != nil {\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:974 (0x104b26174)\n\t(*Command).ExecuteC: err = cmd.execute(flags)\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:902 (0x105673c24)\n\tExecute: _, err := c.ExecuteC()\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:895 (0x105673c1d)\n\t(*Command).ExecuteContext: return c.Execute()\n/Users/o/dev/defradb/cli/cli.go:43 (0x105673bed)\n\tExecute: err := rootCmd.ExecuteContext(ctx)\n/Users/o/dev/defradb/cmd/defradb/main.go:18 (0x10567c270)\n\tmain: cli.Execute()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/proc.go:250 (0x10496acf0)\n\tmain: fn()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/asm_arm64.s:1270 (0x104999634)\n\tgoexit: MOVD\tR0, R0\t// NOP\n", "Error": "OK", "ErrorVerbose": "OK. Stack: /Users/o/dev/defradb/cli/ping.go:29 (0x105676845)\n\tglob..func7: log.FeedbackErrorE(cmd.Context(), \"OK\", errors.New(\"OK\"))\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:856 (0x104b25b84)\n\t(*Command).execute: if err := c.RunE(c, argWoFlags); err != nil {\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:974 (0x104b26174)\n\t(*Command).ExecuteC: err = cmd.execute(flags)\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:902 (0x105673c24)\n\tExecute: _, err := c.ExecuteC()\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:895 (0x105673c1d)\n\t(*Command).ExecuteContext: return c.Execute()\n/Users/o/dev/defradb/cli/cli.go:43 (0x105673bed)\n\tExecute: err := rootCmd.ExecuteContext(ctx)\n/Users/o/dev/defradb/cmd/defradb/main.go:18 (0x10567c270)\n\tmain: cli.Execute()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/proc.go:250 (0x10496acf0)\n\tmain: fn()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/asm_arm64.s:1270 (0x104999634)\n\tgoexit: MOVD\tR0, R0\t// NOP\n", "stacktrace": "OK. Stack: /Users/o/dev/defradb/cli/ping.go:29 (0x105676845)\n\tglob..func7: log.FeedbackErrorE(cmd.Context(), \"OK\", errors.New(\"OK\"))\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:856 (0x104b25b84)\n\t(*Command).execute: if err := c.RunE(c, argWoFlags); err != nil {\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:974 (0x104b26174)\n\t(*Command).ExecuteC: err = cmd.execute(flags)\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:902 (0x105673c24)\n\tExecute: _, err := c.ExecuteC()\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:895 (0x105673c1d)\n\t(*Command).ExecuteContext: return c.Execute()\n/Users/o/dev/defradb/cli/cli.go:43 (0x105673bed)\n\tExecute: err := rootCmd.ExecuteContext(ctx)\n/Users/o/dev/defradb/cmd/defradb/main.go:18 (0x10567c270)\n\tmain: cli.Execute()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/proc.go:250 (0x10496acf0)\n\tmain: fn()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/asm_arm64.s:1270 (0x104999634)\n\tgoexit: MOVD\tR0, R0\t// NOP\n"}

prettified:

{
    "stacktrace": "OK. Stack: /Users/o/dev/defradb/cli/ping.go:29 (0x105676845)\n\tglob..func7: log.FeedbackErrorE(cmd.Context(), \"OK\", errors.New(\"OK\"))\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:856 (0x104b25b84)\n\t(*Command).execute: if err := c.RunE(c, argWoFlags); err != nil {\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:974 (0x104b26174)\n\t(*Command).ExecuteC: err = cmd.execute(flags)\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:902 (0x105673c24)\n\tExecute: _, err := c.ExecuteC()\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:895 (0x105673c1d)\n\t(*Command).ExecuteContext: return c.Execute()\n/Users/o/dev/defradb/cli/cli.go:43 (0x105673bed)\n\tExecute: err := rootCmd.ExecuteContext(ctx)\n/Users/o/dev/defradb/cmd/defradb/main.go:18 (0x10567c270)\n\tmain: cli.Execute()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/proc.go:250 (0x10496acf0)\n\tmain: fn()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/asm_arm64.s:1270 (0x104999634)\n\tgoexit: MOVD\tR0, R0\t// NOP\n",
    "Error": "OK",
    "ErrorVerbose": "OK. Stack: /Users/o/dev/defradb/cli/ping.go:29 (0x105676845)\n\tglob..func7: log.FeedbackErrorE(cmd.Context(), \"OK\", errors.New(\"OK\"))\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:856 (0x104b25b84)\n\t(*Command).execute: if err := c.RunE(c, argWoFlags); err != nil {\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:974 (0x104b26174)\n\t(*Command).ExecuteC: err = cmd.execute(flags)\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:902 (0x105673c24)\n\tExecute: _, err := c.ExecuteC()\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:895 (0x105673c1d)\n\t(*Command).ExecuteContext: return c.Execute()\n/Users/o/dev/defradb/cli/cli.go:43 (0x105673bed)\n\tExecute: err := rootCmd.ExecuteContext(ctx)\n/Users/o/dev/defradb/cmd/defradb/main.go:18 (0x10567c270)\n\tmain: cli.Execute()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/proc.go:250 (0x10496acf0)\n\tmain: fn()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/asm_arm64.s:1270 (0x104999634)\n\tgoexit: MOVD\tR0, R0\t// NOP\n",
    "stacktrace": "OK. Stack: /Users/o/dev/defradb/cli/ping.go:29 (0x105676845)\n\tglob..func7: log.FeedbackErrorE(cmd.Context(), \"OK\", errors.New(\"OK\"))\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:856 (0x104b25b84)\n\t(*Command).execute: if err := c.RunE(c, argWoFlags); err != nil {\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:974 (0x104b26174)\n\t(*Command).ExecuteC: err = cmd.execute(flags)\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:902 (0x105673c24)\n\tExecute: _, err := c.ExecuteC()\n/Users/o/go/pkg/mod/github.com/spf13/[email protected]/command.go:895 (0x105673c1d)\n\t(*Command).ExecuteContext: return c.Execute()\n/Users/o/dev/defradb/cli/cli.go:43 (0x105673bed)\n\tExecute: err := rootCmd.ExecuteContext(ctx)\n/Users/o/dev/defradb/cmd/defradb/main.go:18 (0x10567c270)\n\tmain: cli.Execute()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/proc.go:250 (0x10496acf0)\n\tmain: fn()\n/opt/homebrew/Cellar/[email protected]/1.18.6/libexec/src/runtime/asm_arm64.s:1270 (0x104999634)\n\tgoexit: MOVD\tR0, R0\t// NOP\n"
}

@orpheuslummis
Copy link
Contributor

issue: even when the stacktrace option is disabled in configuration, the stacktrace is still included in the ErrorVerbose

@fredcarle fredcarle force-pushed the fredcarle/chore/handling-errors branch from 2ddb043 to 59ebf79 Compare September 15, 2022 21:08
@fredcarle
Copy link
Collaborator Author

@orpheuslummis the points you brought up are all taken care of with the latest commit. Let me know if you're happy with the changes and I'll merge.

@codecov
Copy link

codecov bot commented Sep 15, 2022

Codecov Report

Merging #794 (58862bf) into develop (89c6a8f) will increase coverage by 0.03%.
The diff coverage is 13.83%.

Impacted file tree graph

@@             Coverage Diff             @@
##           develop     #794      +/-   ##
===========================================
+ Coverage    59.55%   59.58%   +0.03%     
===========================================
  Files          154      154              
  Lines        17219    17245      +26     
===========================================
+ Hits         10254    10275      +21     
- Misses        6039     6044       +5     
  Partials       926      926              
Impacted Files Coverage Δ
cli/addreplicator.go 5.12% <0.00%> (ø)
cli/blocks_get.go 4.25% <0.00%> (ø)
cli/cli.go 20.31% <0.00%> (ø)
cli/dump.go 4.76% <0.00%> (ø)
cli/init.go 37.50% <0.00%> (ø)
cli/peerid.go 37.28% <0.00%> (ø)
cli/ping.go 4.87% <0.00%> (ø)
cli/query.go 2.40% <0.00%> (ø)
cli/root.go 47.67% <0.00%> (ø)
cli/schema_add.go 3.15% <0.00%> (ø)
... and 73 more

@orpheuslummis
Copy link
Contributor

seems like an issue: when log.ErrorE a wrapped error, it won't have the stacktrace in the stacktrace value:

e.g.

log.ErrorE(cmd.Context(), "err msg", fmt.Errorf("WRAP: %w", errors.New("an error")))

->

2022-09-15T16:27:21.755-0500, ERROR, defra.cli, err msg, {"Error": "WRAP: an error", "stacktrace": "WRAP: an error"}`

Copy link
Contributor

@orpheuslummis orpheuslummis left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@fredcarle fredcarle force-pushed the fredcarle/chore/handling-errors branch from 71bc966 to 58862bf Compare September 16, 2022 14:44
@fredcarle fredcarle merged commit f58062b into develop Sep 16, 2022
@fredcarle fredcarle deleted the fredcarle/chore/handling-errors branch September 16, 2022 15:22
shahzadlone pushed a commit to shahzadlone/defradb that referenced this pull request Feb 23, 2024
…work#794)

Description
This PR moves our error handling from the standard library errors package to our own errors package. It also removes the logger stacktrace default which logs the stacktrace at the line of logging and introduces stacktrace logging from the creation of the error.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
action/no-benchmark Skips the action that runs the benchmark. area/errors Related to the internal management or design of our error handling system area/logging Related to the logging/logger system
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Use error stacktrace when logging stacktrace Replace standard errors with defra errors
4 participants