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

restart eBPF tracking on error #2735

Merged
merged 3 commits into from Aug 18, 2017

Conversation

Projects
None yet
3 participants
@alban
Collaborator

alban commented Jul 20, 2017

This is a workaround for #2650

Tested manually the following way:

Start Scope with:

    sudo WEAVESCOPE_DOCKER_ARGS="-e SCOPE_DEBUG_BPF=1" ./scope launch

Simulate EbpfTracker failure with:

    echo foo | sudo tee /proc/$(pidof scope-probe)/root/var/run/scope/debug-bpf

TODO:

@@ -287,10 +310,33 @@ func (t *EbpfTracker) isDead() bool {
func (t *EbpfTracker) stop() {
t.Lock()
defer t.Unlock()

This comment has been minimized.

@rade

rade Jul 20, 2017

Member

I deliberately didn't do this, because it requires a lot of assumptions about the behaviour of tracer, in order to avoid deadlocks. It's fine right now.

Was there a specific reason why you changed this?

This comment has been minimized.

@alban

alban Jul 24, 2017

Collaborator

I see your point. No specific reason. I'll change it back.

This comment has been minimized.

@alban

alban Jul 24, 2017

Collaborator

Actually, it fails if I let the Unlock as it was before:

<probe> WARN: 2017/07/24 13:45:09.816261 ebpf tracker stopped as requested by user
<probe> WARN: 2017/07/24 13:45:10.304710 ebpf tracker died, trying to restart it
<probe> WARN: 2017/07/24 13:45:10.312468 could not restart ebpf tracker, falling back to proc scanning: cannot write "p:ptcp_v4_connect tcp_v4_connect\n" to kprobe_events: write /sys/kernel/debug/tracing/kprobe_events: device or resource busy

The stop is done in the event handler thread, when I receive an event with a wrong timestamp. And the restart is done in the publisher thread when it notices that isDead == true. I think that the publisher thread starts the restart before the tracer is fully stopped, so the kprobe is not completely removed yet...

tracer.Start()
return nil
}

This comment has been minimized.

@rade

rade Jul 20, 2017

Member

I'd be wary of holding the lock while calling tracer.Start().

Also, newEbpfTracker() should be refactored to call this.

This comment has been minimized.

@alban

alban Jul 24, 2017

Collaborator

ok

@alban alban force-pushed the kinvolk:alban/bpf-restart branch 2 times, most recently from 9efe6fc to 1de8096 Jul 24, 2017

@alban

This comment has been minimized.

Collaborator

alban commented Jul 24, 2017

I updated the code. It seems to restart fine. But I had one instance of my test where Scope was talking 100% of the cpu in the gobpf code when I tested the fallback to proc parsing.

I got the stack of the go routine taking all the cpu with the following command. The stack changes all the time since it is running.

sudo WEAVESCOPE_DOCKER_ARGS="-e SCOPE_DEBUG_BPF=1" ./scope launch --probe.http.listen :4041
http://localhost:4041/debug/pprof/goroutine?debug=2
goroutine 4442 [runnable, locked to thread]:
github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf._C2func_poll(0xc42385aea0, 0x4, 0x1f4, 0x4, 0x0, 0x0)
	github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf/_obj/_cgo_gotypes.go:313 +0x68
github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf.perfEventPoll(0xc4218f0e40, 0x4, 0x4, 0xc42385ae00, 0xc423857510)
	/go/src/github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf/perf.go:258 +0xf6
github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf.(*PerfMap).PollStart.func1(0xc42026c910, 0xc4245df1c0, 0xc4245db180)
	/go/src/github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf/perf.go:171 +0x695
created by github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf.(*PerfMap).PollStart
	/go/src/github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf/perf.go:238 +0xf1

Also, the integration test needs fixing too: https://circleci.com/gh/kinvolk/scope/990
integration/313_container_to_container_edge_with_ebpf_proc_fallback_test.sh

@alban alban force-pushed the kinvolk:alban/bpf-restart branch 2 times, most recently from 64b8ca0 to 58b3361 Jul 25, 2017

@alban

This comment has been minimized.

Collaborator

alban commented Jul 25, 2017

I fixed the regression in integration test 313 and added a new integration test 315 that restarts EbpfTracker.

@alban alban changed the title from [WIP] restart eBPF tracking on error to restart eBPF tracking on error Jul 25, 2017

@rade rade requested a review from 2opremio Jul 25, 2017

closedDuringInit: map[fourTuple]struct{}{},
var debugBPF bool
if os.Getenv("SCOPE_DEBUG_BPF") != "" {
log.Warnf("ebpf tracker started in debug mode")

This comment has been minimized.

@2opremio

2opremio Jul 31, 2017

Collaborator

I would make this an Info

This comment has been minimized.

@alban

alban Aug 7, 2017

Collaborator

ok

@@ -220,6 +221,8 @@ func TestInvalidTimeStampDead(t *testing.T) {
if cnt != 2 {
t.Errorf("walkConnections found %v instead of 2 connections", cnt)
}
// EbpfTracker is marked as dead asynchronously.
time.Sleep(100 * time.Millisecond)

This comment has been minimized.

@2opremio

2opremio Jul 31, 2017

Collaborator

Can't you poll with a timeout? magic sleep times lead to flaky tests.

This comment has been minimized.

@alban

alban Aug 7, 2017

Collaborator

ok, will do

}
t.ebpfFailureTime = time.Now()
if t.ebpfFailureCount == 0 {

This comment has been minimized.

@2opremio

2opremio Jul 31, 2017

Collaborator

This logic is hard to read. I don't think there's a need to split this in multiple blocks. I think it's preferable to repeat the t.useProcfs(). Also, it's more idiomatic in Go to check for errors in ifs and continue with the least erroneous path. Something like the following is easier to read and shorter.

t.ebpfFailureTime = time.Now()
// Multiple failures in the last 5 minutes, fall back to proc parsing
if t.ebpfFailureCount > 0 && t.ebpfFailureTime.After(time.Now().Add(-5*time.Minute))  {
   log.Warnf("ebpf tracker died again, gently falling back to proc scanning")
   t.useProcfs()
   return
}

// Tolerable failure rate, let's just reset the failure count and restart the tracker
t.ebpfFailureCount = 0
log.Warnf("ebpf tracker died, restarting it")
if err := t.ebpfTracker.restart(); err != nil {
  log.Warnf("could not restart ebpf tracker, falling back to proc scanning: %v", err)
  t.useProcfs()
  return
}

go t.getInitialState()
t.performEbpfTrack(rpt, hostNodeID)
return

This comment has been minimized.

@alban

alban Aug 7, 2017

Collaborator

I'll simplify this.

t.useProcfs() is not at the end of the function though, so repeating it before a return won't work.

@@ -29,6 +30,9 @@ type connectionTracker struct {
flowWalker flowWalker // Interface
ebpfTracker *EbpfTracker
reverseResolver *reverseResolver
ebpfFailureCount int
ebpfFailureTime time.Time

This comment has been minimized.

@2opremio

2opremio Jul 31, 2017

Collaborator

Wouldn't it be more accurate to call this ebpfLastFailureTime?

This comment has been minimized.

@alban

alban Aug 7, 2017

Collaborator

👍

@@ -29,6 +30,9 @@ type connectionTracker struct {
flowWalker flowWalker // Interface
ebpfTracker *EbpfTracker
reverseResolver *reverseResolver
ebpfFailureCount int

This comment has been minimized.

@2opremio

2opremio Jul 31, 2017

Collaborator

Do we need counts here? We only check it to be higher than 0, right? then we can simply make it a boolean and call it didEBPFFail?

This comment has been minimized.

@2opremio

2opremio Jul 31, 2017

Collaborator

In fact, I think we can remove this altogether and use the zero value of time (https://golang.org/pkg/time/#Time.IsZero ) to reset the failures.

This comment has been minimized.

@alban

alban Aug 7, 2017

Collaborator

ok, I will remove ebpfFailureCount

t.tracer.Stop()
// Do not call tracer.Stop() in this thread, otherwise tracer.Stop() will
// deadlock waiting for this thread to pick up the next event.

This comment has been minimized.

@2opremio

2opremio Jul 31, 2017

Collaborator

How would it deadlock? I am probably missing something, but Stop() just seems to close the channel, which should be fine.

This comment has been minimized.

@2opremio

2opremio Jul 31, 2017

Collaborator

In other words why can't stop() simply be:

t.Lock()
defer t.Unlock()
if !t.dead {
  return
}
t.tracer.Stop()
t.tracer = nil
t.dead = true

This comment has been minimized.

@2opremio

2opremio Jul 31, 2017

Collaborator

BTW, the stopChan channel should have a higher priority than the other channels here: https://github.com/weaveworks/tcptracer-bpf/blob/master/pkg/tracer/tracer.go#L80-L99

This comment has been minimized.

@alban

alban Aug 7, 2017

Collaborator

The deadlock was not with tcptracer-bpf's channel t.stopChan but with gobpf's channels:

  • t.perfMapIPV4.PollStop() / pm.pollStop <- true (perf.go#L244)
  • pm.receiverChan <- incoming.bytesArray[0] (perf.go#L229)

I could reliably reproduce the deadlock before using pprof to print the go routine stacks (following this doc).

Maybe this should be fixed at the gobpf level but I don't immediately see how, because the caller of gobpf's PollStop() needs to know when it's done...

t.ebpfFailureCount++
err := t.ebpfTracker.restart()
if err == nil {
go t.getInitialState()

This comment has been minimized.

@2opremio

2opremio Jul 31, 2017

Collaborator

Shouldn't the invocation of getInitialState() be part of the tracker initialization in restart()?

This comment has been minimized.

@2opremio

2opremio Jul 31, 2017

Collaborator

We seem to always call it immediately after it.

This comment has been minimized.

@alban

alban Aug 7, 2017

Collaborator

yes, but getInitialState() uses other objects besides just ebpfTracker, such as consulting conntrack. And restart() in ebpf.go is independent from conntrack. So better to keep it separate.

@alban alban force-pushed the kinvolk:alban/bpf-restart branch from 8050079 to 5575556 Aug 8, 2017

@alban

This comment has been minimized.

Collaborator

alban commented Aug 8, 2017

Branch updated.

@alban

This comment has been minimized.

Collaborator

alban commented Aug 8, 2017

Tests:

  • CircleCI passes
  • tested manually on my laptop (simulating EbpfTracker failure)
  • tested on the GCE instance with the test script to reproduce it the bug

It seemed to work fine.

But then, I had a look at the go routine stacks with pprof after Scope fell back on proc parsing:

goroutine 26 [chan send, 4 minutes]:
github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf.(*PerfMap).PollStart.func1(0xc4202c0370, 0xc422dbbf00, 0xc423f508a0)
	/go/src/github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf/perf.go:229 +0x4f7
created by github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf.(*PerfMap).PollStart
	/go/src/github.com/weaveworks/scope/vendor/github.com/weaveworks/tcptracer-bpf/vendor/github.com/iovisor/gobpf/elf/perf.go:238 +0xf1
  • the go routine in gobpf should not be there anymore but it is. It does not take CPU, but that's still a leak. Probably related to @2opremio 's comment #2735 (comment)
  • the go import path shows a double vendoring. Is it expected?
@alban

This comment has been minimized.

Collaborator

alban commented Aug 8, 2017

Fix in gobpf, tested on GCE: https://gist.github.com/alban/cb4b899e9558e231d080ec7e7b3abbc5
Explanation: https://github.com/iovisor/gobpf/blob/d0a3e1b/elf/perf.go#L241-L242

It seems to resolve the leaking go routine. I'll do the PR tomorrow. weaveworks/tcptracer-bpf#49

alban added a commit to kinvolk/tcptracer-bpf that referenced this pull request Aug 8, 2017

tracer: close channels on Stop()
PerfMap's PollStop() documentation says the channel should be closed
after calling PollStop():
https://github.com/iovisor/gobpf/blob/d0a3e1b/elf/perf.go#L241-L242

This is solving a leaking go routine issue in Scope:
weaveworks/scope#2735 (comment)

alban added a commit to kinvolk/tcptracer-bpf that referenced this pull request Aug 9, 2017

tracer: close channels on Stop()
PerfMap's PollStop() documentation says the channel should be closed
after calling PollStop():
https://github.com/iovisor/gobpf/blob/d0a3e1b/elf/perf.go#L241-L242

This is solving a leaking go routine issue in Scope:
weaveworks/scope#2735 (comment)

@alban alban changed the title from restart eBPF tracking on error to [WIP] restart eBPF tracking on error Aug 9, 2017

@alban

This comment has been minimized.

Collaborator

alban commented Aug 9, 2017

I updated the vendoring with weaveworks/tcptracer-bpf#49 and marked this PR as WIP because the dependency is not merged yet.

@alban alban referenced this pull request Aug 17, 2017

Merged

vendor: update gobpf #50

alban added some commits Jul 20, 2017

EbpfTracker: restart it when it dies
EbpfTracker can die when the tcp events are received out of order. This
can happen with a buggy kernel or apparently in other cases, see:
#2650

As a workaround, restart EbpfTracker when an event is received out of
order. This does not seem to happen often, but as a precaution,
EbpfTracker will not restart if the last failure is less than 5 minutes
ago.

This is not easy to test but I added instrumentation to trigger a
restart:

- Start Scope with:
    $ sudo WEAVESCOPE_DOCKER_ARGS="-e SCOPE_DEBUG_BPF=1" ./scope launch

- Request a stop with:
    $ echo stop | sudo tee /proc/$(pidof scope-probe)/root/var/run/scope/debug-bpf

@alban alban force-pushed the kinvolk:alban/bpf-restart branch from 82d597c to 760fd2c Aug 17, 2017

@alban

This comment has been minimized.

Collaborator

alban commented Aug 17, 2017

I updated the PR (pending on weaveworks/tcptracer-bpf#50) and it works for me now. I don't see leaking go routines nor panics anymore. I tested several times both with waiting 5 minutes between the ebpf tracker crashes and without waiting.

vendor: update tcptracer-bpf and gobpf
This includes:

- iovisor/gobpf#70
  perf: close go channels idiomatically

- iovisor/gobpf#70
  close channels on the sender side & fix closing race

- weaveworks/tcptracer-bpf#50
  vendor: update gobpf

@alban alban force-pushed the kinvolk:alban/bpf-restart branch from 760fd2c to 93ca8b8 Aug 17, 2017

@alban alban changed the title from [WIP] restart eBPF tracking on error to restart eBPF tracking on error Aug 17, 2017

@alban

This comment has been minimized.

Collaborator

alban commented Aug 17, 2017

@2opremio new review welcome :)

@rade rade merged commit 8fe3538 into weaveworks:master Aug 18, 2017

2 checks passed

ci/circleci Your tests passed on CircleCI!
Details
deploy/netlify Deploy preview ready!
Details
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment