Fatal error when a connection is attempted to a BGP speaker running BIRD2

[DominikPohl]

Hey,

First of all:
Thanks for the cool project! Looks like a really neat way to do creative BGP scripting stuff in the future.

I wanted to test it with a lab router (running BIRD2 v2.0.12) but as soon as bgpipe received/exchanged the OPEN message a fatal error occurs and bgpipe crashes:

Command line arguments for bgpipe:

./bgpipe \
    --log debug \
    -- connect 10.10.10.1:179 \
    -- speaker --active --asn 65000 --id 10.10.10.2 \
    -- write --append bgp.log

Relevant BIRD2 config would be:

protocol bgp BGPPIPE_TEST {
    local 10.10.10.1 as CFG_ASN port 179;
    neighbor 10.10.10.2 as 65000;

    ipv4 {
        import none;
        export where filterExportDownstreamFull(65000);
    };
}

Content of the log file is:

["R",1,"2024-05-22T21:43:24.777",-1,"OPEN",{"bgp":4,"asn":65000,"id":"10.10.10.2","hold":90,"caps":{"MP":["IPV4/UNICAST","IPV4/FLOWSPEC","IPV6/UNICAST","IPV6/FLOWSPEC"],"ROUTE_REFRESH":true,"EXTENDED_MESSAGE":true,"AS4":65000}},{}]

And the error output itself:

2024-05-22 21:43:24 DBG [1] attached connect -R [FIRST] stage="[1] connect"
2024-05-22 21:43:24 DBG [2] attached speaker -R stage="[2] speaker"
2024-05-22 21:43:24 DBG [3] attached write -R [LAST] stage="[3] write"
2024-05-22 21:43:24 DBG starting ev=E1:bgpfix/pipe.START stage="[3] write"
2024-05-22 21:43:24 INF opening bgp.log stage="[3] write"
2024-05-22 21:43:24 DBG starting ev=E1:bgpfix/pipe.START stage="[2] speaker"
2024-05-22 21:43:24 DBG starting ev=E1:bgpfix/pipe.START stage="[1] connect"
2024-05-22 21:43:24 INF dialing 10.10.10.1:179 stage="[1] connect"
2024-05-22 21:43:24 DBG closing L inputs
2024-05-22 21:43:24 DBG closing R output
2024-05-22 21:43:24 INF connected 10.10.10.1:40704 -> 10.10.10.1:179 stage="[1] connect"
2024-05-22 21:43:24 INF connection closed read=0 stage="[1] connect" wrote=0
2024-05-22 21:43:24 DBG stopping ev=nil stage="[1] connect"
2024-05-22 21:43:24 DBG closing L output
fatal error: all goroutines are asleep - deadlock!

goroutine 1 [chan receive]:
github.com/bgpfix/bgpfix/pipe.(*Line).Wait(...)
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/line.go:83
github.com/bgpfix/bgpfix/pipe.(*Pipe).Wait(0xc000150000)
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/pipe.go:227 +0x5f
github.com/bgpfix/bgpipe/core.(*Bgpipe).Run(0xc000132100)
        /Users/pforemski/pjf/bgpfix/bgpipe/core/bgpipe.go:90 +0x239
main.main()
        /Users/pforemski/pjf/bgpfix/bgpipe/main.go:15 +0x3a

goroutine 8 [chan receive]:
github.com/bgpfix/bgpfix/pipe.(*Input).process(0xc00011edd8)
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/input.go:160 +0xc5
created by github.com/bgpfix/bgpfix/pipe.(*Line).start in goroutine 1
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/line.go:68 +0x3c

goroutine 10 [chan receive]:
github.com/bgpfix/bgpfix/pipe.(*Input).process(0xc00017e800)
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/input.go:160 +0xc5
created by github.com/bgpfix/bgpfix/pipe.(*Line).start in goroutine 1
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/line.go:68 +0x3c

goroutine 11 [chan receive]:
github.com/bgpfix/bgpfix/pipe.(*Input).Wait(...)
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/input.go:289
github.com/bgpfix/bgpfix/pipe.(*Line).start.func1()
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/line.go:74 +0x4f
created by github.com/bgpfix/bgpfix/pipe.(*Line).start in goroutine 1
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/line.go:72 +0xd8

goroutine 12 [chan receive]:
github.com/bgpfix/bgpfix/pipe.(*Line).Wait(...)
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/line.go:83
github.com/bgpfix/bgpfix/pipe.(*Pipe).Start.func1()
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/pipe.go:176 +0x45
created by github.com/bgpfix/bgpfix/pipe.(*Pipe).Start in goroutine 1
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/pipe.go:174 +0x98

goroutine 13 [chan receive]:
github.com/bgpfix/bgpfix/pipe.(*Pipe).eventHandler(0xc000150000, 0xc0001500c0)
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/event.go:218 +0x105
created by github.com/bgpfix/bgpfix/pipe.(*Pipe).Start in goroutine 1
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/pipe.go:182 +0x107

goroutine 14 [chan receive]:
github.com/bgpfix/bgpfix/pipe.(*Pipe).Start.func2()
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/pipe.go:186 +0x32
created by github.com/bgpfix/bgpfix/pipe.(*Pipe).Start in goroutine 1
        /Users/pforemski/go/pkg/mod/github.com/bgpfix/bgpfix@v0.3.0/pipe/pipe.go:185 +0x145

goroutine 16 [chan receive]:
github.com/bgpfix/bgpipe/stages.(*Write).Run(0xc00015a100)
        /Users/pforemski/pjf/bgpfix/bgpipe/stages/write.go:151 +0xe9
github.com/bgpfix/bgpipe/core.(*StageBase).runStart.func2()
        /Users/pforemski/pjf/bgpfix/bgpipe/core/run.go:69 +0x148
created by github.com/bgpfix/bgpipe/core.(*StageBase).runStart in goroutine 13
        /Users/pforemski/pjf/bgpfix/bgpipe/core/run.go:53 +0x369

goroutine 17 [chan receive]:
github.com/bgpfix/bgpipe/core.(*StageBase).Run(0xc000024b60)
        /Users/pforemski/pjf/bgpfix/bgpipe/core/stage.go:108 +0x31
github.com/bgpfix/bgpipe/core.(*StageBase).runStart.func2()
        /Users/pforemski/pjf/bgpfix/bgpipe/core/run.go:69 +0x148
created by github.com/bgpfix/bgpipe/core.(*StageBase).runStart in goroutine 13
        /Users/pforemski/pjf/bgpfix/bgpipe/core/run.go:53 +0x369

goroutine 21 [semacquire]:
sync.runtime_Semacquire(0x0?)
        /Users/pforemski/local/go/src/runtime/sema.go:62 +0x25
sync.(*WaitGroup).Wait(0x0?)
        /Users/pforemski/local/go/src/sync/waitgroup.go:116 +0x48
github.com/bgpfix/bgpipe/core.(*Bgpipe).Start.func2()
        /Users/pforemski/pjf/bgpfix/bgpipe/core/bgpipe.go:117 +0x2c
created by github.com/bgpfix/bgpipe/core.(*Bgpipe).Start in goroutine 13
        /Users/pforemski/pjf/bgpfix/bgpipe/core/bgpipe.go:116 +0x96

Let me know if you need further details.
I'll be happy to assist!

Best regards,
Dominik

[pforemski]

Hey, thanks for the bug report and kind words - clearly there's work to do on how to handle errors better :)

From logs it seems the BIRD side has closed its TCP connection without sending anything - do you have any logs from BIRD that can confirm this and/or explain why it happened?

If possible, could you record a .pcap file of the BGP conversation that ends with this result?

[pforemski]

Ah, and also please try the following bgpipe command-line instead:

./bgpipe \
    --log debug \
    -- connect 10.10.10.1:179 \
    -- write --append bgp.log \
    -- speaker --active --asn 65000 --id 10.10.10.2

that is, move the write stage in the middle between BIRD and speaker. Also, if you want to capture messages in both directions, use write -LR for that.

[DominikPohl]

After some testing i got it working now. Dont know what the exact issue was but i initially tried to run bgpipe on the same VM that BIRD is running on just on a different locally attached IP and different port.

Now i moved bgpipe to a different VM and it just started working without any issues.

So i can only assume that it was some sort of an BIRD error. Sorry for ringing the alarm bells. False positive 😅

On a positive note: Everything seems to work now. I can see all the updates/routes comming in (MultiProtocol is also working just fine) ✨

Attached is a PCAP of the successful connection (stopped midway through to not blow up the PCAP size)
BGP-Capture.zip

[pforemski]

Great, thank you!

And I was able to reproduce this in the meantime. It is not at all an issue with BIRD.

The scary bgpipe log dump is a problem how bgpipe reports errors and handles pipelines with no more data to process. I will make sure to better support & document pipeline config for users in the future. Thanks for your feedback!