Question about logging with 3.0.1

[Nigel Kukard]

Hi there Jana,

On 2/24/25 16:25, Jana Babovakova wrote:
> Hi Nigel.
>
> I suspect this is due to BIRD 3 working as multi-thread. In the 
> migration guide there is a note about that:
>
> "
>
>
>     Logging
>
> Log files have a slightly different format, indicating by |[abcd]| the 
> actual thread logging the message. This enables the user to better 
> comprehend what's actually going on between interleaved messages from 
> different threads, especially when detailed route tracing is on.
>
> There is also a new logging option, a fixed-size circular logfile. 
> This is handy if you need to switch on detailed tracing but you don't 
> want to overfill your disk. Also this option is by far the fastest one.
>
> "

I did see this in the migration guide, but even a single "print" in a 
filter seems to loop continuously to the log file very many times per 
second.

For comparison, Bird v2 had around 200 log lines after a few minutes, 
Bird v3 before I killed it after 30s or so was at 1.17M lines.

Is this intended behavior with v3? (it pretty much means I cannot log in 
my filters anymore). I just want to confirm so I can remove the print 
messages.

Kind Regards
Nigel


>
> I hope this helps.
> Kind regards,
> Jana
>
> Jana Babovakova | BIRD Tech Support | CZ.NIC, z.s.p.o.
> On 24. 02. 25 16:54, Nigel Kukard via Bird-users wrote:
>> Hi there,
>>
>> I'm wondering if anyone has seen excessive filter logging with 
>> 3.0.0/3.0.1?
>>
>> Comparing log output from tests done on v2 vs v3, I'm seeing 2G+ log 
>> files generated in 30s on v3, when in v2 the log files were only a 
>> few hundred Kb in size at most after some time.
>>
>> I have router R1 and R2 connected via BGP. I have a couple of filters 
>> which log if a prefix has been filtered or accepted, I've included my 
>> log configuration and filter below.
>>
>> Here is the log config I'm using...
>>
>>
>> log "/var/log/bird.log" { info, warning, fatal };
>> debug protocols { states, routes, filters, interfaces, events };
>> timeformat base iso long;
>> timeformat log iso long;
>> timeformat protocol iso long;
>> timeformat route iso long;
>>
>>
>> Here is the test filter I created to test...
>>
>> define DEFAULT_ROUTE_V4 = 0.0.0.0/0;
>> define DEFAULT_ROUTE_V6 = ::/0;
>>
>> function is_default(string filter_name) -> bool {
>>     if ((net.type = NET_IP4 && net = DEFAULT_ROUTE_V4) || (net.type = 
>> NET_IP6 && net = DEFAULT_ROUTE_V6)) then
>>         return true;
>>     return false;
>> }
>>
>> function bgp_accept_bgp(string filter_name) -> bool {
>>     if (is_default()) then return false;
>>     print filter_name, " [bgp_accept_bgp] Accepting BGP route ", net, 
>> " from ", proto;
>>     accept;
>> }
>>
>> filter f_bgp_master_export
>> string filter_name;
>> {
>>   filter_name = "f_bgp_master_export";
>>   bgp_accept_bgp(filter_name);
>>   reject;
>> };
>>
>>
>> Here is the odd behavior I"m observing in v3...
>>
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.111.0.0/24 from bgp4_AS65000_r1
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.112.0.0/24 from bgp4_AS65000_r1
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.113.0.0/24 from bgp4_AS65000_r1
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.201.0.0/24 from bgp4_AS65000_r1
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.131.0.0/24 from bgp4_AS65000_r1
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.132.0.0/24 from bgp4_AS65000_r1
>>
>> repeating very many times per second...
>>
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.111.0.0/24 from bgp4_AS65000_r1
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.112.0.0/24 from bgp4_AS65000_r1
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.113.0.0/24 from bgp4_AS65000_r1
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.201.0.0/24 from bgp4_AS65000_r1
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.131.0.0/24 from bgp4_AS65000_r1
>> 2025-02-24 15:21:04 [0002] <INFO> f_bgp_master_export 
>> [bgp_accept_bgp] Accepting BGP route 100.132.0.0/24 from bgp4_AS65000_r1
>>
>> In about 30s my log file grew to 2.1GB before I stopped the process.
>>
>> Perhaps I'm missing something in the migration guide? any help would 
>> be greatly appreciated.
>>
>> Kind Regards
>> Nigel
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://trubka.network.cz/pipermail/bird-users/attachments/20250224/b7c5e4f5/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: OpenPGP_signature.asc
Type: application/pgp-signature
Size: 236 bytes
Desc: OpenPGP digital signature
URL: <http://trubka.network.cz/pipermail/bird-users/attachments/20250224/b7c5e4f5/attachment.sig>