Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543
Hi, (please keep me in CC, thanks) I got the following somewhat strangely formatted log lines in /var/log/messages on a BIRD v2.0.6 instance connected to routinator3000 v0.5 ("r3k" bellow) running on FreeBSD 12: kernel: 8-48 AS2119 kernel: CS_UP' failed at nest/rt-table.c:1543 kernel: 9-22T00:59:04.466158+01:00 - - Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 kernel: Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 kernel: 6f8::/32-32 AS25525 kernel: :59:05.654000+01:00 bird 1144 - - Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 kernel: P' failed at nest/rt-table.c:1543 kernel: acket (81.89.96.0/20-20 AS35366) kernel: nel_state == CS_UP' failed at nest/rt-table.c:1543 kernel: at nest/rt-table.c:1543 kernel: 22T00:59:10.355042+01:00 bird 1144 - - r3k: Received IPv4 Prefix packet (46.252.16.0/20-24 AS20738) kernel: ate == CS_UP' failed at nest/rt-table.c:1543 kernel: 0 bird 1144 - - Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 kernel: 9)
On Sun, Sep 22, 2019 at 01:10:00AM +0200, Christoph wrote:
Hi, (please keep me in CC, thanks)
I got the following somewhat strangely formatted log lines in /var/log/messages on a BIRD v2.0.6 instance connected to routinator3000 v0.5 ("r3k" bellow) running on FreeBSD 12:
Hi That is an interesting issue. What was your configuration and can you replicate it and get output of 'show protocols all' ? -- Elen sila lumenn' omentielvo Ondrej 'Santiago' Zajicek (email: santiago@crfreenet.org) OpenPGP encrypted e-mails preferred (KeyID 0x11DEADC3, wwwkeys.pgp.net) "To err is human -- to blame it on a computer is even more so."
On Sun, Sep 22, 2019 at 01:10:00AM +0200, Christoph wrote:
Hi, (please keep me in CC, thanks)
I got the following somewhat strangely formatted log lines in /var/log/messages on a BIRD v2.0.6 instance connected to routinator3000 v0.5 ("r3k" bellow) running on FreeBSD 12:
Hi
That is an interesting issue. What was your configuration and can you replicate it and get output of 'show protocols all' ?
Yes it happens every time bird gets a ROA via RTR. I reduced the config to a minimum (BGP peers commented out): BIRD 2.0.6 ready. bird> s p Name Proto Table State Since Info r3k RPKI --- start 00:53:06.027 Established device1 Device --- up 00:53:06.027 mynet4 Static master4 up 00:53:06.027 mynet6 Static master6 up 00:53:06.027 kernel1 Kernel master4 up 00:53:06.027 kernel2 Kernel master6 up 00:53:06.027 bird> s p a Name Proto Table State Since Info r3k RPKI --- start 00:53:06.027 Established Cache server: 127.0.0.1:1323 Status: Established Transport: Unprotected over TCP Protocol version: 1 Session ID: 1325 Serial number: 0 Last update: before 40.453 s Refresh timer : 859.546/900 Retry timer : --- Expire timer : 7159.546/7200 Channel roa4 State: START Table: r4 Preference: 100 Input filter: ACCEPT Output filter: REJECT Routes: 90604 imported, 0 exported, 90604 preferred Route change stats: received rejected filtered ignored accepted Import updates: 90604 0 0 0 90604 Import withdraws: 0 0 --- 0 0 Export updates: 0 0 0 --- 0 Export withdraws: 0 --- --- --- 0 Channel roa6 State: START Table: r6 Preference: 100 Input filter: ACCEPT Output filter: REJECT Routes: 15571 imported, 0 exported, 15571 preferred Route change stats: received rejected filtered ignored accepted Import updates: 15571 0 0 0 15571 Import withdraws: 0 0 --- 0 0 Export updates: 0 0 0 --- 0 Export withdraws: 0 --- --- --- 0 [...] debug log: <TRACE> r3k > added [best] 43.245.16.0/24-24 AS10024 <TRACE> r3k: Received IPv6 Prefix packet (2406:480::/32-32 AS59374) <DBG> Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 <TRACE> r3k > added [best] 2406:480::/32-32 AS59374 <TRACE> r3k: Received IPv4 Prefix packet (212.104.48.0/21-21 AS9076) <DBG> Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 <TRACE> r3k > added [best] 212.104.48.0/21-21 AS9076 <TRACE> r3k: Received IPv4 Prefix packet (77.104.64.0/18-18 AS42337) <DBG> Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 [...] RPKI config: ------------- roa4 table r4; roa6 table r6; protocol rpki r3k { roa4 { table r4; }; roa6 { table r6; }; remote 127.0.0.1 port 1323; retry keep 15; refresh keep 900; expire 14400; } -------------
On Sun, Sep 22, 2019 at 10:01:00PM +0000, Christoph wrote:
On Sun, Sep 22, 2019 at 01:10:00AM +0200, Christoph wrote:
Hi, (please keep me in CC, thanks)
I got the following somewhat strangely formatted log lines in /var/log/messages on a BIRD v2.0.6 instance connected to routinator3000 v0.5 ("r3k" bellow) running on FreeBSD 12:
Hi
That is an interesting issue. What was your configuration and can you replicate it and get output of 'show protocols all' ?
Yes it happens every time bird gets a ROA via RTR.
I reduced the config to a minimum (BGP peers commented out):
If you can add 'debug { events, states };' option to the RPKI option, could you send me the logs during protocol initialization? There should be some part with 'Connected' and 'Changing ... state'. -- Elen sila lumenn' omentielvo Ondrej 'Santiago' Zajicek (email: santiago@crfreenet.org) OpenPGP encrypted e-mails preferred (KeyID 0x11DEADC3, wwwkeys.pgp.net) "To err is human -- to blame it on a computer is even more so."
If you can add 'debug { events, states };' option to the RPKI option, could you send me the logs during protocol initialization? There should be some part with 'Connected' and 'Changing ... state'.
I disabled and enabled it to trigger a sync: disable r3k enable r3k log (not sure if this helps): 2019-09-23 19:09:37.098 <INFO> Enabling protocol r3k 2019-09-23 19:09:37.098 <TRACE> r3k: Starting 2019-09-23 19:09:37.098 <TRACE> r3k: Changing from Down to Connecting state 2019-09-23 19:09:37.098 <TRACE> r3k: Opening a connection 2019-09-23 19:09:37.098 <TRACE> r3k: Connected 2019-09-23 19:09:37.098 <TRACE> r3k: State changed to up 2019-09-23 19:09:37.098 <TRACE> r3k: Changing from Connecting to Sync-Start state 2019-09-23 19:09:37.098 <TRACE> r3k: State changed to start 2019-09-23 19:09:37.120 <TRACE> r3k: Changing from Sync-Start to Sync-Running state 2019-09-23 19:09:37.121 <DBG> Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 2019-09-23 19:09:37.121 <DBG> Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 2019-09-23 19:09:37.121 <DBG> Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 2019-09-23 19:09:37.121 <DBG> Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 [...] 2019-09-23 19:09:51.531 <DBG> Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 2019-09-23 19:09:51.531 <DBG> Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 2019-09-23 19:09:51.531 <DBG> Assertion 'c->channel_state == CS_UP' failed at nest/rt-table.c:1543 2019-09-23 19:09:51.531 <TRACE> r3k: New interval values: refresh: keeps 900s, retry: keeps 15s, expire: 7200s 2019-09-23 19:09:51.531 <TRACE> r3k: Changing from Sync-Running to Established state config: ----------- roa4 table r4; roa6 table r6; protocol rpki r3k { debug { events, states }; roa4 { table r4; }; roa6 { table r6; }; remote 127.0.0.1 port 1323; retry keep 15; refresh keep 900; expire 14400; } -----------
On Mon, Sep 23, 2019 at 04:18:00PM +0000, Christoph wrote:
If you can add 'debug { events, states };' option to the RPKI option, could you send me the logs during protocol initialization? There should be some part with 'Connected' and 'Changing ... state'.
I disabled and enabled it to trigger a sync:
disable r3k enable r3k
log (not sure if this helps):
2019-09-23 19:09:37.098 <INFO> Enabling protocol r3k 2019-09-23 19:09:37.098 <TRACE> r3k: Starting 2019-09-23 19:09:37.098 <TRACE> r3k: Changing from Down to Connecting state 2019-09-23 19:09:37.098 <TRACE> r3k: Opening a connection 2019-09-23 19:09:37.098 <TRACE> r3k: Connected 2019-09-23 19:09:37.098 <TRACE> r3k: State changed to up 2019-09-23 19:09:37.098 <TRACE> r3k: Changing from Connecting to Sync-Start state 2019-09-23 19:09:37.098 <TRACE> r3k: State changed to start
Thanks. This is strange, the protocol goes correctly to up state, but then immediately fell back to start state for no obvious reason. -- Elen sila lumenn' omentielvo Ondrej 'Santiago' Zajicek (email: santiago@crfreenet.org) OpenPGP encrypted e-mails preferred (KeyID 0x11DEADC3, wwwkeys.pgp.net) "To err is human -- to blame it on a computer is even more so."
participants (2)
-
Christoph -
Ondrej Zajicek