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

internal: support optional filter expression for debug.stacks #23605

Merged
merged 3 commits into from Sep 20, 2021

Conversation

karalabe
Copy link
Member

@karalabe karalabe commented Sep 20, 2021

Whenever Geth hangs, we use the debug.stacks API endpoint to try and find what might be off. This is fine-ish, but it generates a huge dump of goroutines and it's quite a pain to find a needle in the haystack and see if there's something wrong or not.

The initial idea was to add a filter parameter where we can specify packages to filter for, potentially multiple - comma separated - but even that produces too much noise. Adding both inclusion filters and exclusion filters would be necessary, but that would get both nasty as well as probably still not flexible enough.

The solution is to use a single filter that can contain both inclusion and exclusion clauses, as well as the possibility to combine these arbitrarily. Without hinting further, the only way to solve it is to have the filter be a boolean expression that gets evaluated runtime and returns those goroutines which evaluate to true.

The PR uses HashiCorp's boolean expression parser and evaluator, but to keep the filter complexity down, I've defined a simpler purpose-built syntax that gets transformed under the hood to the one used by bexpr. Our filter language consists of:

  • String words to search for in the traces (e.g. /downloader/, handler.go, wait)
  • Logical expressions to combine clauses && and || (e.g. downloader || snap)
  • Logical negation to turn an inclusion filter into exclusion ! (e.g. snap && !p2p)
    • Note, negation can only be used in front of a word for now. You can't exclude a paranthesis.
  • Parentheses to allow arbitrarily complex filters (e.g. (downloader || snap) && select)

@karalabe karalabe added this to the 1.10.9 milestone Sep 20, 2021
@holiman
Copy link
Contributor

holiman commented Sep 20, 2021

I don't understand what I'm doing wrong. geth --dev console

> debug.stacks("receive && console")
INFO [09-20|10:53:52.912] Expanded filter expression               filter="receive && console" expanded="`receive` in Value and `console` in Value"
goroutine 1 [chan receive]:
github.com/ethereum/go-ethereum/internal/jsre.(*JSRE).Do(...)
	github.com/ethereum/go-ethereum/internal/jsre/jsre.go:227
github.com/ethereum/go-ethereum/internal/jsre.(*JSRE).Evaluate(0xc0000edfc0, {0xc0001cd4d0, 0x23}, {0x1615d60, 0xc0001a6008})
	github.com/ethereum/go-ethereum/internal/jsre/jsre.go:274 +0x129
github.com/ethereum/go-ethereum/console.(*Console).Evaluate(0xc0001cd4d0, {0xc0001cd4d0, 0x0})
	github.com/ethereum/go-ethereum/console/console.go:339 +0x68
github.com/ethereum/go-ethereum/console.(*Console).Interactive(0xc0001c4e00)
	github.com/ethereum/go-ethereum/console/console.go:410 +0x705
main.localConsole(0xc0001186e0)
	github.com/ethereum/go-ethereum/cmd/geth/consolecmd.go:108 +0x31f
github.com/ethereum/go-ethereum/cmd/utils.MigrateFlags.func1(0xc0001186e0)
	github.com/ethereum/go-ethereum/cmd/utils/flags.go:1929 +0x48
gopkg.in/urfave/cli%2ev1.HandleAction({0x11be6e0, 0xc0005a4ad0}, 0x7)
	gopkg.in/urfave/cli.v1@v1.20.0/app.go:490 +0x5a
gopkg.in/urfave/cli%2ev1.Command.Run({{0x13cd6ff, 0x7}, {0x0, 0x0}, {0x0, 0x0, 0x0}, {0x1402ec3, 0x2b}, {0x0, ...}, ...}, ...)
	gopkg.in/urfave/cli.v1@v1.20.0/command.go:210 +0x8f8
gopkg.in/urfave/cli%2ev1.(*App).Run(0xc0003f44e0, {0xc000192150, 0x3, 0x3})
	gopkg.in/urfave/cli.v1@v1.20.0/app.go:255 +0x6ac
main.main()
	github.com/ethereum/go-ethereum/cmd/geth/main.go:254 +0x35

goroutine 181 [chan receive]:
github.com/ethereum/go-ethereum/console.(*Console).readLines(0xc0001c4e00, 0xc00024a0b8, 0xc000cc8a80, 0xc0003b57b0)
	github.com/ethereum/go-ethereum/console/console.go:419 +0x46
created by github.com/ethereum/go-ethereum/console.(*Console).Interactive
	github.com/ethereum/go-ethereum/console/console.go:363 +0x1ef



null
> debug.stacks("receive && /console/")
INFO [09-20|10:53:58.477] Expanded filter expression               filter="receive && /console/" expanded="`receive` in Value and /`console` in Value/"
ERROR[09-20|10:53:58.478] Failed to parse filter expression        expanded="`receive` in Value and /`console` in Value/" err="1:24 (23): no match found, expected: \"(\", \"-\", \"0\", \"\\\"\", \"`\", \"not\", [ \\t\\r\\n], [1-9] or [a-zA-Z]"
""


goroutine 165 [select]:
github.com/ethereum/go-ethereum/rpc.(*requestOp).wait(0xc000d12dc0, {0x1637330, 0xc0001ae000}, 0xc0005e1380)
github.com/ethereum/go-ethereum/rpc/client.go:136 +0xae
github.com/ethereum/go-ethereum/rpc.(*Client).CallContext(0xc0005e1380, {0x1637330, 0xc0001ae000}, {0x1220fe0, 0xc00019ee40}, {0xc0000c4ce0, 0xc}, {0xc000d12d80, 0x1, 0x4})
github.com/ethereum/go-ethereum/rpc/client.go:311 +0x251
github.com/ethereum/go-ethereum/rpc.(*Client).Call(...)
github.com/ethereum/go-ethereum/rpc/client.go:283
github.com/ethereum/go-ethereum/console.(*bridge).Send(0xc0003034a0, {{{0x165af58, 0xc0014dfc98}, {0xc001036290, 0x1, 0x13}}, 0xc0004b2780})
github.com/ethereum/go-ethereum/console/bridge.go:415 +0x708
github.com/ethereum/go-ethereum/internal/jsre.MakeCallback.func1({{0x165af58, 0xc0014dfc98}, {0xc001036290, 0x1, 0x13}})
github.com/ethereum/go-ethereum/internal/jsre/jsre.go:264 +0xad
github.com/dop251/goja.(*vm)._nativeCall(0xc0003f1790, 0xc0014ffce0, 0x1)
github.com/dop251/goja@v0.0.0-20200721192441-a695b0cdd498/vm.go:1795 +0x2fa
github.com/dop251/goja.call.exec(0x4, 0xc0003f1790)
github.com/dop251/goja@v0.0.0-20200721192441-a695b0cdd498/vm.go:1779 +0x3a7
github.com/dop251/goja.(*vm).run(0xc0003f1790)
github.com/dop251/goja@v0.0.0-20200721192441-a695b0cdd498/vm.go:289 +0x8b
github.com/dop251/goja.(*vm).try(0x0, 0x10196a0)
github.com/dop251/goja@v0.0.0-20200721192441-a695b0cdd498/vm.go:383 +0x132
github.com/dop251/goja.(*vm).runTry(...)
github.com/dop251/goja@v0.0.0-20200721192441-a695b0cdd498/vm.go:388
github.com/dop251/goja.(*Runtime).RunProgram(0xc0004b2780, 0x0)
github.com/dop251/goja@v0.0.0-20200721192441-a695b0cdd498/runtime.go:900 +0x298
github.com/dop251/goja.(*Runtime).RunScript(0xc0004aab40, {0x0, 0xc000248628}, {0xc0001a5d10, 0x0})
github.com/dop251/goja@v0.0.0-20200721192441-a695b0cdd498/runtime.go:879 +0x65
github.com/dop251/goja.(*Runtime).RunString(...)
github.com/dop251/goja@v0.0.0-20200721192441-a695b0cdd498/runtime.go:868
github.com/ethereum/go-ethereum/internal/jsre.(*JSRE).Evaluate.func1(0xc00102bf20)
github.com/ethereum/go-ethereum/internal/jsre/jsre.go:275 +0x45
github.com/ethereum/go-ethereum/internal/jsre.(*JSRE).runEventLoop(0xc0000edfc0)
github.com/ethereum/go-ethereum/internal/jsre/jsre.go:204 +0x50c
created by github.com/ethereum/go-ethereum/internal/jsre.New
github.com/ethereum/go-ethereum/internal/jsre/jsre.go:79 +0x195


null
> debug.stacks("client.go")
INFO [09-20|10:51:29.980] Expanded filter expression               filter=client.go          expanded="`client` in Value.`go` in Value"
ERROR[09-20|10:51:29.980] Failed to parse filter expression        expanded="`client` in Value.`go` in Value" err="1:19 (18): no match found, expected: [0-9] or [a-zA-Z]"``

@holiman
Copy link
Contributor

holiman commented Sep 20, 2021

It seems to split up .go into a separate entity:

INFO [09-20|10:56:36.849] Expanded filter expression               filter="IO && netpoll"        expanded="`IO` in Value and `netpoll` in Value"
goroutine 41 [IO wait, 6 minutes]:
internal/poll.runtime_pollWait(0x711aac1b2760, 0x72)
	runtime/netpoll.go:229 +0x89
internal/poll.(*pollDesc).wait(0xc0005e0f80, 0x20, 0x0)
	internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc0005e0f80)
	internal/poll/fd_unix.go:402 +0x22c
net.(*netFD).accept(0xc0005e0f80)
	net/fd_unix.go:173 +0x35
net.(*UnixListener).accept(0x0)
	net/unixsock_posix.go:167 +0x1c
net.(*UnixListener).Accept(0xc0005dced0)
	net/unixsock.go:260 +0x3d
github.com/ethereum/go-ethereum/rpc.(*Server).ServeListener(0xc00041d770, {0x1626cd0, 0xc0005dced0})
	github.com/ethereum/go-ethereum/rpc/ipc.go:30 +0x5b
created by github.com/ethereum/go-ethereum/rpc.StartIPCEndpoint
	github.com/ethereum/go-ethereum/rpc/endpoints.go:50 +0x206


null
> debug.stacks("IO && netpoll.go")
INFO [09-20|10:56:41.880] Expanded filter expression               filter="IO && netpoll.go"     expanded="`IO` in Value and `netpoll` in Value.`go` in Value"
ERROR[09-20|10:56:41.880] Failed to parse filter expression        expanded="`IO` in Value and `netpoll` in Value.`go` in Value" err="1:38 (37): no match found, expected: [0-9] or [a-zA-Z]"
""
> 

expanded="`IO` in Value and `netpoll` in Value.`go` in Value"

@karalabe
Copy link
Member Author

@holiman Sorry about that, made the last min modification to not auto-expand into /foobard/ syntax, rather require it manually and didn't add / (and .) to the string matcher regexp. Should work now (TM)

@holiman
Copy link
Contributor

holiman commented Sep 20, 2021

Would be pretty neat if this was supported too:

> debug.stacks("console.go")
INFO [09-20|12:33:08.339] Expanded filter expression               filter=console.go              expanded="`console.go` in Value"
goroutine 1 [chan receive]:
github.com/ethereum/go-ethereum/internal/jsre.(*JSRE).Do(...)
	github.com/ethereum/go-ethereum/internal/jsre/jsre.go:227
github.com/ethereum/go-ethereum/internal/jsre.(*JSRE).Evaluate(0xc000543340, {0xc0005df460, 0x1b}, {0x1615d60, 0xc00012e008})
	github.com/ethereum/go-ethereum/internal/jsre/jsre.go:274 +0x129
github.com/ethereum/go-ethereum/console.(*Console).Evaluate(0xc0005df460, {0xc0005df460, 0x0})
	github.com/ethereum/go-ethereum/console/console.go:339 +0x68
github.com/ethereum/go-ethereum/console.(*Console).Interactive(0xc00014cb60)
	github.com/ethereum/go-ethereum/console/console.go:410 +0x705
main.localConsole(0xc00009e580)
	github.com/ethereum/go-ethereum/cmd/geth/consolecmd.go:108 +0x31f
github.com/ethereum/go-ethereum/cmd/utils.MigrateFlags.func1(0xc00009e580)
	github.com/ethereum/go-ethereum/cmd/utils/flags.go:1929 +0x48
gopkg.in/urfave/cli%2ev1.HandleAction({0x11be6e0, 0xc000079900}, 0x7)
	gopkg.in/urfave/cli.v1@v1.20.0/app.go:490 +0x5a
gopkg.in/urfave/cli%2ev1.Command.Run({{0x13cd6ff, 0x7}, {0x0, 0x0}, {0x0, 0x0, 0x0}, {0x1402ec9, 0x2b}, {0x0, ...}, ...}, ...)
	gopkg.in/urfave/cli.v1@v1.20.0/command.go:210 +0x8f8
gopkg.in/urfave/cli%2ev1.(*App).Run(0xc000241d40, {0xc00011a150, 0x3, 0x3})
	gopkg.in/urfave/cli.v1@v1.20.0/app.go:255 +0x6ac
main.main()
	github.com/ethereum/go-ethereum/cmd/geth/main.go:254 +0x35

goroutine 155 [chan receive]:
github.com/ethereum/go-ethereum/console.(*Console).readLines(0xc00014cb60, 0xc000210148, 0xc000df46c0, 0xc000201fb0)
	github.com/ethereum/go-ethereum/console/console.go:419 +0x46
created by github.com/ethereum/go-ethereum/console.(*Console).Interactive
	github.com/ethereum/go-ethereum/console/console.go:363 +0x1ef



null
> debug.stacks("console.go:339 ")
INFO [09-20|12:33:12.790] Expanded filter expression               filter="console.go:339 "       expanded="`console.go` in Value:`339` in Value "
ERROR[09-20|12:33:12.791] Failed to parse filter expression        expanded="`console.go` in Value:`339` in Value " err="1:22 (21): no match found, expected: \".\", \"[\", [ \\t\\r\\n], [a-zA-Z0-9_/] or EOF"
""

Comment on lines 210 to 211
expanded = regexp.MustCompile("[/\\.A-Za-z0-9_-]+").ReplaceAllString(expanded, "`$0` in Value")
expanded = regexp.MustCompile("!(`[/\\.A-Za-z0-9_-]+`)").ReplaceAllString(expanded, "$1 not")
Copy link
Contributor

@holiman holiman Sep 20, 2021

Choose a reason for hiding this comment

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

Suggested change
expanded = regexp.MustCompile("[/\\.A-Za-z0-9_-]+").ReplaceAllString(expanded, "`$0` in Value")
expanded = regexp.MustCompile("!(`[/\\.A-Za-z0-9_-]+`)").ReplaceAllString(expanded, "$1 not")
expanded = regexp.MustCompile("[/\\:.A-Za-z0-9_-]+").ReplaceAllString(expanded, "`$0` in Value")
expanded = regexp.MustCompile("!(`[/\\:.A-Za-z0-9_-]+`)").ReplaceAllString(expanded, "$1 not")

For

> debug.stacks("console.go:419")
INFO [09-20|13:22:16.459] Expanded filter expression               filter=console.go:419 expanded="`console.go:419` in Value"
goroutine 140 [chan receive]:
github.com/ethereum/go-ethereum/console.(*Console).readLines(0xc000596310, 0xc0004566e8, 0xc000dc3ff0, 0xc0000bb7b0)
	github.com/ethereum/go-ethereum/console/console.go:419 +0x46
created by github.com/ethereum/go-ethereum/console.(*Console).Interactive
	github.com/ethereum/go-ethereum/console/console.go:363 +0x1ef

Copy link
Member Author

Choose a reason for hiding this comment

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

Just move the : to the front of the regexp. I think the - must be the last, otherwise it's interpreted as an interval i.e. from _ to :

Copy link
Contributor

Choose a reason for hiding this comment

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

Done. THat's actually how I had it in my own code, but when I wrote the comment here I moved it. WCGW right? ;)

Copy link
Contributor

@holiman holiman left a comment

Choose a reason for hiding this comment

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

LGTM once : is supported

@karalabe karalabe merged commit e28f713 into ethereum:master Sep 20, 2021
yongjun925 pushed a commit to DODOEX/go-ethereum that referenced this pull request Dec 3, 2022
…um#23605)

* internal: support optional filter expression for debug.stacks

* internal/debug: fix string regexp

* internal/debug: support searching for line numbers too
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants