Nest: Per-channel debug flags

The patch add support for per-channel debug flags, currently just
'states', 'routes', and 'filters'. Flag 'states' is used for channel
state changes, remaining two for routes passed through the channel.
The per-protocol debug flags 'routes'/'filters' still enable reporting
of routes for all channels, to keep existing behavior.

The patch causes minor changes in some log messages.
This commit is contained in:
Ondrej Zajicek (work) 2020-12-07 22:19:40 +01:00
parent 8cc5bb09e3
commit 61dae32b29
7 changed files with 117 additions and 72 deletions

View file

@ -32,8 +32,9 @@ struct config {
struct iface_patt *router_id_from; /* Configured list of router ID iface patterns */
u32 router_id; /* Our Router ID */
unsigned proto_default_debug; /* Default protocol debug mask */
unsigned proto_default_mrtdump; /* Default protocol mrtdump mask */
u32 proto_default_debug; /* Default protocol debug mask */
u32 proto_default_mrtdump; /* Default protocol mrtdump mask */
u32 channel_default_debug; /* Default channel debug mask */
struct timeformat tf_route; /* Time format for 'show route' */
struct timeformat tf_proto; /* Time format for 'show protocol' */
struct timeformat tf_log; /* Time format for the logfile */

View file

@ -64,6 +64,7 @@ CF_DECLS
const char *t;
struct rtable_config *r;
struct channel_config *cc;
struct channel *c;
struct f_inst *x;
struct {
struct f_inst *begin, *end;

View file

@ -91,7 +91,7 @@ CF_KEYWORDS(ROUTER, ID, PROTOCOL, TEMPLATE, PREFERENCE, DISABLED, DEBUG, ALL, OF
CF_KEYWORDS(INTERFACE, IMPORT, EXPORT, FILTER, NONE, VRF, DEFAULT, TABLE, STATES, ROUTES, FILTERS)
CF_KEYWORDS(IPV4, IPV6, VPN4, VPN6, ROA4, ROA6, FLOW4, FLOW6, SADR, MPLS)
CF_KEYWORDS(RECEIVE, LIMIT, ACTION, WARN, BLOCK, RESTART, DISABLE, KEEP, FILTERED)
CF_KEYWORDS(PASSWORD, FROM, PASSIVE, TO, ID, EVENTS, PACKETS, PROTOCOLS, INTERFACES)
CF_KEYWORDS(PASSWORD, FROM, PASSIVE, TO, ID, EVENTS, PACKETS, PROTOCOLS, CHANNELS, INTERFACES)
CF_KEYWORDS(ALGORITHM, KEYED, HMAC, MD5, SHA1, SHA256, SHA384, SHA512)
CF_KEYWORDS(PRIMARY, STATS, COUNT, BY, FOR, COMMANDS, PREEXPORT, NOEXPORT, EXPORTED, GENERATE)
CF_KEYWORDS(BGP, PASSWORDS, DESCRIPTION, SORTED)
@ -123,7 +123,8 @@ CF_ENUM_PX(T_ENUM_AF, AF_, AFI_, IPV4, IPV6)
%type <cl> limit_spec
%type <net> r_args_for_val
%type <net_ptr> r_args_for
%type <t> r_args_channel
%type <t> channel_sym
%type <c> channel_arg
CF_GRAMMAR
@ -247,7 +248,7 @@ channel_start: net_type
$$ = this_channel = channel_config_get(NULL, net_label[$1], $1, this_proto);
};
channel_item:
channel_item_:
TABLE rtable {
if (this_channel->net_type && ($2->addr_type != this_channel->net_type))
cf_error("Incompatible table type");
@ -262,6 +263,12 @@ channel_item:
| IMPORT KEEP FILTERED bool { this_channel->in_keep_filtered = $4; }
;
/* To avoid grammar collision in Pipe protocol */
channel_item:
channel_item_
| DEBUG debug_mask { this_channel->debug = $2; }
;
channel_opts:
/* empty */
| channel_opts channel_item ';'
@ -310,6 +317,7 @@ conf: debug_default ;
debug_default:
DEBUG PROTOCOLS debug_mask { new_config->proto_default_debug = $3; }
| DEBUG CHANNELS debug_mask { new_config->channel_default_debug = $3; }
| DEBUG COMMANDS expr { new_config->cli_debug = $3; }
;
@ -604,26 +612,14 @@ r_args:
rt_show_add_table($$, t->table);
$$->tables_defined_by = RSD_TDB_ALL;
}
| r_args IMPORT TABLE CF_SYM_KNOWN '.' r_args_channel {
cf_assert_symbol($4, SYM_PROTO);
$$ = $1;
struct proto_config *cf = $4->proto;
if (!cf->proto) cf_error("%s is not a protocol", $4->name);
struct channel *c = proto_find_channel_by_name(cf->proto, $6);
if (!c) cf_error("Channel %s.%s not found", $4->name, $6);
if (!c->in_table) cf_error("No import table in channel %s.%s", $4->name, $6);
rt_show_add_table($$, c->in_table);
| r_args IMPORT TABLE channel_arg {
if (!$4->in_table) cf_error("No import table in channel %s.%s", $4->proto->name, $4->name);
rt_show_add_table($$, $4->in_table);
$$->tables_defined_by = RSD_TDB_DIRECT;
}
| r_args EXPORT TABLE CF_SYM_KNOWN '.' r_args_channel {
cf_assert_symbol($4, SYM_PROTO);
$$ = $1;
struct proto_config *cf = $4->proto;
if (!cf->proto) cf_error("%s is not a protocol", $4->name);
struct channel *c = proto_find_channel_by_name(cf->proto, $6);
if (!c) cf_error("Channel %s.%s not found", $4->name, $6);
if (!c->out_table) cf_error("No export table in channel %s.%s", $4->name, $6);
rt_show_add_table($$, c->out_table);
| r_args EXPORT TABLE channel_arg {
if (!$4->out_table) cf_error("No export table in channel %s.%s", $4->proto->name, $4->name);
rt_show_add_table($$, $4->out_table);
$$->tables_defined_by = RSD_TDB_DIRECT;
}
| r_args FILTER filter {
@ -658,15 +654,11 @@ r_args:
$$->export_protocol = c->proto;
$$->tables_defined_by = RSD_TDB_INDIRECT;
}
| r_args export_mode CF_SYM_KNOWN '.' r_args_channel {
cf_assert_symbol($3, SYM_PROTO);
struct proto_config *c = (struct proto_config *) $3->proto;
| r_args export_mode channel_arg {
$$ = $1;
if ($$->export_mode) cf_error("Export specified twice");
if (!c->proto) cf_error("%s is not a protocol", $3->name);
$$->export_mode = $2;
$$->export_channel = proto_find_channel_by_name(c->proto, $5);
if (!$$->export_channel) cf_error("Export channel not found");
$$->export_channel = $3;
$$->tables_defined_by = RSD_TDB_INDIRECT;
}
| r_args PROTOCOL CF_SYM_KNOWN {
@ -735,7 +727,7 @@ export_mode:
;
/* This is ugly hack */
r_args_channel:
channel_sym:
IPV4 { $$ = "ipv4"; }
| IPV4_MC { $$ = "ipv4-mc"; }
| IPV4_MPLS { $$ = "ipv4-mpls"; }
@ -758,6 +750,16 @@ r_args_channel:
| SEC { $$ = "sec"; }
;
channel_arg:
CF_SYM_KNOWN '.' channel_sym {
cf_assert_symbol($1, SYM_PROTO);
struct proto *p = $1->proto->proto;
if (!p) cf_error("%s is not a protocol", $1->name);
$$ = proto_find_channel_by_name(p, $3);
if (!$$) cf_error("Channel %s.%s not found", $1->name, $3);
}
;
CF_CLI_HELP(SHOW SYMBOLS, ..., [[Show all known symbolic names]])
CF_CLI(SHOW SYMBOLS, sym_args, [table|filter|function|protocol|template|<symbol>], [[Show all known symbolic names]])
{ cmd_show_symbols($3); } ;
@ -832,8 +834,13 @@ CF_CLI(RELOAD OUT, proto_patt, <protocol> | \"<pattern>\" | all, [[Reload protoc
{ proto_apply_cmd($3, proto_cmd_reload, 1, CMD_RELOAD_OUT); } ;
CF_CLI_HELP(DEBUG, ..., [[Control protocol debugging via BIRD logs]])
CF_CLI(DEBUG, proto_patt debug_mask, (<protocol> | \"<pattern>\" | all) (all | off | { states|routes|filters|interfaces|events|packets [, ...] }), [[Control protocol debugging via BIRD logs]])
{ proto_apply_cmd($2, proto_cmd_debug, 1, $3); } ;
CF_CLI(DEBUG, debug_args, (<protocol> | <channel> | \"<pattern>\" | all) (all | off | { states|routes|filters|interfaces|events|packets [, ...] }), [[Control protocol debugging via BIRD logs]])
{ /* Done in debug_args */ };
debug_args:
proto_patt debug_mask { proto_apply_cmd($1, proto_cmd_debug, 1, $2); }
| channel_arg debug_mask { channel_cmd_debug($1, $2); }
;
CF_CLI_HELP(MRTDUMP, ..., [[Control protocol debugging via MRTdump files]])
CF_CLI(MRTDUMP, proto_patt mrtdump_mask, (<protocol> | \"<pattern>\" | all) (all | off | { states|messages [, ...] }), [[Control protocol debugging via MRTdump format]])

View file

@ -27,7 +27,8 @@ list proto_list;
static list protocol_list;
struct protocol *class_to_protocol[PROTOCOL__MAX];
#define PD(pr, msg, args...) do { if (pr->debug & D_STATES) { log(L_TRACE "%s: " msg, pr->name , ## args); } } while(0)
#define CD(c, msg, args...) ({ if (c->debug & D_STATES) log(L_TRACE "%s.%s: " msg, c->proto->name, c->name ?: "?", ## args); })
#define PD(p, msg, args...) ({ if (p->debug & D_STATES) log(L_TRACE "%s: " msg, p->name, ## args); })
static timer *proto_shutdown_timer;
static timer *gr_wait_timer;
@ -42,6 +43,7 @@ static u32 graceful_restart_locks;
static char *p_states[] = { "DOWN", "START", "UP", "STOP" };
static char *c_states[] = { "DOWN", "START", "UP", "FLUSHING" };
static char *e_states[] = { "DOWN", "FEEDING", "READY" };
extern struct protocol proto_unix_iface;
@ -58,6 +60,15 @@ static inline int proto_is_done(struct proto *p)
static inline int channel_is_active(struct channel *c)
{ return (c->channel_state == CS_START) || (c->channel_state == CS_UP); }
static inline void
channel_log_state_change(struct channel *c)
{
if (c->export_state)
CD(c, "State changed to %s/%s", c_states[c->channel_state], e_states[c->export_state]);
else
CD(c, "State changed to %s", c_states[c->channel_state]);
}
static void
proto_log_state_change(struct proto *p)
{
@ -159,6 +170,7 @@ proto_add_channel(struct proto *p, struct channel_config *cf)
c->net_type = cf->net_type;
c->ra_mode = cf->ra_mode;
c->preference = cf->preference;
c->debug = cf->debug;
c->merge_limit = cf->merge_limit;
c->in_keep_filtered = cf->in_keep_filtered;
@ -172,17 +184,17 @@ proto_add_channel(struct proto *p, struct channel_config *cf)
add_tail(&p->channels, &c->n);
PD(p, "Channel %s connected to table %s", c->name, c->table->name);
CD(c, "Connected to table %s", c->table->name);
return c;
}
void
proto_remove_channel(struct proto *p, struct channel *c)
proto_remove_channel(struct proto *p UNUSED, struct channel *c)
{
ASSERT(c->channel_state == CS_DOWN);
PD(p, "Channel %s removed", c->name);
CD(c, "Removed", c->name);
rem_node(&c->n);
mb_free(c);
@ -273,7 +285,7 @@ channel_feed_loop(void *ptr)
// DBG("Feeding protocol %s finished\n", p->name);
c->export_state = ES_READY;
// proto_log_state_change(p);
channel_log_state_change(c);
if (c->proto->feed_end)
c->proto->feed_end(c);
@ -498,7 +510,8 @@ channel_set_state(struct channel *c, uint state)
default:
ASSERT(0);
}
// XXXX proto_log_state_change(c);
channel_log_state_change(c);
}
/**
@ -516,6 +529,8 @@ channel_request_feeding(struct channel *c)
{
ASSERT(c->channel_state == CS_UP);
CD(c, "Feeding requested");
/* Do nothing if we are still waiting for feeding */
if (c->export_state == ES_DOWN)
return;
@ -534,7 +549,7 @@ channel_request_feeding(struct channel *c)
c->refeed_count = 0;
channel_schedule_feed(c, 0); /* Sets ES_FEEDING */
// proto_log_state_change(c);
channel_log_state_change(c);
}
static inline int
@ -549,6 +564,8 @@ channel_request_reload(struct channel *c)
ASSERT(c->channel_state == CS_UP);
ASSERT(channel_reloadable(c));
CD(c, "Reload requested");
c->proto->reload_routes(c);
/*
@ -594,6 +611,7 @@ channel_config_new(const struct channel_class *cc, const char *name, uint net_ty
cf->net_type = net_type;
cf->ra_mode = RA_OPTIMAL;
cf->preference = proto->protocol->preference;
cf->debug = new_config->channel_default_debug;
add_tail(&proto->channels, &cf->n);
@ -663,6 +681,7 @@ channel_reconfigure(struct channel *c, struct channel_config *cf)
// c->ra_mode = cf->ra_mode;
c->merge_limit = cf->merge_limit;
c->preference = cf->preference;
c->debug = cf->debug;
c->in_keep_filtered = cf->in_keep_filtered;
channel_verify_limits(c);
@ -676,7 +695,7 @@ channel_reconfigure(struct channel *c, struct channel_config *cf)
/* If the channel is not open, it has no routes and we cannot reload it anyways */
if (c->channel_state != CS_UP)
return 1;
goto done;
if (reconfigure_type == RECONFIG_SOFT)
{
@ -686,7 +705,7 @@ channel_reconfigure(struct channel *c, struct channel_config *cf)
if (export_changed)
log(L_INFO "Channel %s.%s changed export", c->proto->name, c->name);
return 1;
goto done;
}
/* Route reload may be not supported */
@ -702,6 +721,8 @@ channel_reconfigure(struct channel *c, struct channel_config *cf)
if (export_changed)
channel_request_feeding(c);
done:
CD(c, "Reconfigured");
return 1;
}
@ -1862,6 +1883,16 @@ channel_show_info(struct channel *c)
channel_show_stats(c);
}
void
channel_cmd_debug(struct channel *c, uint mask)
{
if (cli_access_restricted())
return;
c->debug = mask;
cli_msg(0, "");
}
void
proto_cmd_show(struct proto *p, uintptr_t verbose, int cnt)
{

View file

@ -281,6 +281,7 @@ void channel_graceful_restart_unlock(struct channel *c);
void channel_show_limit(struct channel_limit *l, const char *dsc);
void channel_show_info(struct channel *c);
void channel_cmd_debug(struct channel *c, uint mask);
void proto_cmd_show(struct proto *, uintptr_t, int);
void proto_cmd_disable(struct proto *, uintptr_t, int);
@ -496,6 +497,7 @@ struct channel_config {
u8 net_type; /* Routing table network type (NET_*), 0 for undefined */
u8 ra_mode; /* Mode of received route advertisements (RA_*) */
u16 preference; /* Default route preference */
u32 debug; /* Debugging flags (D_*) */
u8 merge_limit; /* Maximal number of nexthops for RA_MERGED */
u8 in_keep_filtered; /* Routes rejected in import filter are kept */
};
@ -524,6 +526,7 @@ struct channel {
u8 net_type; /* Routing table network type (NET_*), 0 for undefined */
u8 ra_mode; /* Mode of received route advertisements (RA_*) */
u16 preference; /* Default route preference */
u32 debug; /* Debugging flags (D_*) */
u8 merge_limit; /* Maximal number of nexthops for RA_MERGED */
u8 in_keep_filtered; /* Routes rejected in import filter are kept */
u8 disabled;

View file

@ -550,23 +550,25 @@ rte_mergable(rte *pri, rte *sec)
}
static void
rte_trace(struct proto *p, rte *e, int dir, char *msg)
rte_trace(struct channel *c, rte *e, int dir, char *msg)
{
log(L_TRACE "%s %c %s %N %s", p->name, dir, msg, e->net->n.addr, rta_dest_name(e->attrs->dest));
log(L_TRACE "%s.%s %c %s %N %s",
c->proto->name, c->name ?: "?", dir, msg, e->net->n.addr,
rta_dest_name(e->attrs->dest));
}
static inline void
rte_trace_in(uint flag, struct proto *p, rte *e, char *msg)
rte_trace_in(uint flag, struct channel *c, rte *e, char *msg)
{
if (p->debug & flag)
rte_trace(p, e, '>', msg);
if ((c->debug & flag) || (c->proto->debug & flag))
rte_trace(c, e, '>', msg);
}
static inline void
rte_trace_out(uint flag, struct proto *p, rte *e, char *msg)
rte_trace_out(uint flag, struct channel *c, rte *e, char *msg)
{
if (p->debug & flag)
rte_trace(p, e, '<', msg);
if ((c->debug & flag) || (c->proto->debug & flag))
rte_trace(c, e, '<', msg);
}
static rte *
@ -589,13 +591,13 @@ export_filter_(struct channel *c, rte *rt0, rte **rt_free, linpool *pool, int si
stats->exp_updates_rejected++;
if (v == RIC_REJECT)
rte_trace_out(D_FILTERS, p, rt, "rejected by protocol");
rte_trace_out(D_FILTERS, c, rt, "rejected by protocol");
goto reject;
}
if (v > 0)
{
if (!silent)
rte_trace_out(D_FILTERS, p, rt, "forced accept by protocol");
rte_trace_out(D_FILTERS, c, rt, "forced accept by protocol");
goto accept;
}
@ -610,7 +612,7 @@ export_filter_(struct channel *c, rte *rt0, rte **rt_free, linpool *pool, int si
goto reject;
stats->exp_updates_filtered++;
rte_trace_out(D_FILTERS, p, rt, "filtered out");
rte_trace_out(D_FILTERS, c, rt, "filtered out");
goto reject;
}
@ -651,7 +653,7 @@ do_rt_notify(struct channel *c, net *net, rte *new, rte *old, int refeed)
if (l->state == PLS_BLOCKED)
{
stats->exp_updates_rejected++;
rte_trace_out(D_FILTERS, p, new, "rejected [limit]");
rte_trace_out(D_FILTERS, c, new, "rejected [limit]");
return;
}
}
@ -680,11 +682,11 @@ do_rt_notify(struct channel *c, net *net, rte *new, rte *old, int refeed)
if (p->debug & D_ROUTES)
{
if (new && old)
rte_trace_out(D_ROUTES, p, new, "replaced");
rte_trace_out(D_ROUTES, c, new, "replaced");
else if (new)
rte_trace_out(D_ROUTES, p, new, "added");
rte_trace_out(D_ROUTES, c, new, "added");
else if (old)
rte_trace_out(D_ROUTES, p, old, "removed");
rte_trace_out(D_ROUTES, c, old, "removed");
}
p->rt_notify(p, c, net, new, old);
@ -1119,7 +1121,7 @@ rte_recalculate(struct channel *c, net *net, rte *new, struct rte_src *src)
if (!rte_is_filtered(new))
{
stats->imp_updates_ignored++;
rte_trace_in(D_ROUTES, p, new, "ignored");
rte_trace_in(D_ROUTES, c, new, "ignored");
}
rte_free_quick(new);
@ -1162,7 +1164,7 @@ rte_recalculate(struct channel *c, net *net, rte *new, struct rte_src *src)
we just free new and exit like nothing happened */
stats->imp_updates_ignored++;
rte_trace_in(D_FILTERS, p, new, "ignored [limit]");
rte_trace_in(D_FILTERS, c, new, "ignored [limit]");
rte_free_quick(new);
return;
}
@ -1184,7 +1186,7 @@ rte_recalculate(struct channel *c, net *net, rte *new, struct rte_src *src)
already handled. */
stats->imp_updates_ignored++;
rte_trace_in(D_FILTERS, p, new, "ignored [limit]");
rte_trace_in(D_FILTERS, c, new, "ignored [limit]");
if (c->in_keep_filtered)
new->flags |= REF_FILTERED;
@ -1316,18 +1318,18 @@ rte_recalculate(struct channel *c, net *net, rte *new, struct rte_src *src)
}
/* Log the route change */
if (p->debug & D_ROUTES)
if ((c->debug & D_ROUTES) || (p->debug & D_ROUTES))
{
if (new_ok)
rte_trace(p, new, '>', new == net->routes ? "added [best]" : "added");
rte_trace(c, new, '>', new == net->routes ? "added [best]" : "added");
else if (old_ok)
{
if (old != old_best)
rte_trace(p, old, '>', "removed");
rte_trace(c, old, '>', "removed");
else if (rte_is_ok(net->routes))
rte_trace(p, old, '>', "removed [replaced]");
rte_trace(c, old, '>', "removed [replaced]");
else
rte_trace(p, old, '>', "removed [sole]");
rte_trace(c, old, '>', "removed [sole]");
}
}
@ -1433,7 +1435,7 @@ rte_unhide_dummy_routes(net *net, rte **dummy)
void
rte_update2(struct channel *c, const net_addr *n, rte *new, struct rte_src *src)
{
struct proto *p = c->proto;
// struct proto *p = c->proto;
struct proto_stats *stats = &c->stats;
const struct filter *filter = c->in_filter;
rte *dummy = NULL;
@ -1458,7 +1460,7 @@ rte_update2(struct channel *c, const net_addr *n, rte *new, struct rte_src *src)
stats->imp_updates_received++;
if (!rte_validate(new))
{
rte_trace_in(D_FILTERS, p, new, "invalid");
rte_trace_in(D_FILTERS, c, new, "invalid");
stats->imp_updates_invalid++;
goto drop;
}
@ -1466,7 +1468,7 @@ rte_update2(struct channel *c, const net_addr *n, rte *new, struct rte_src *src)
if (filter == FILTER_REJECT)
{
stats->imp_updates_filtered++;
rte_trace_in(D_FILTERS, p, new, "filtered out");
rte_trace_in(D_FILTERS, c, new, "filtered out");
if (! c->in_keep_filtered)
goto drop;
@ -1483,7 +1485,7 @@ rte_update2(struct channel *c, const net_addr *n, rte *new, struct rte_src *src)
if (fr > F_ACCEPT)
{
stats->imp_updates_filtered++;
rte_trace_in(D_FILTERS, p, new, "filtered out");
rte_trace_in(D_FILTERS, c, new, "filtered out");
if (! c->in_keep_filtered)
{
@ -2098,7 +2100,7 @@ rt_next_hop_update_net(rtable *tab, net *n)
new = rt_next_hop_update_rte(tab, e);
*k = new;
rte_trace_in(D_ROUTES, new->sender->proto, new, "updated");
rte_trace_in(D_ROUTES, new->sender, new, "updated");
rte_announce_i(tab, RA_ANY, n, new, e, NULL, NULL);
/* Call a pre-comparison hook */
@ -2137,7 +2139,7 @@ rt_next_hop_update_net(rtable *tab, net *n)
/* Announce the new best route */
if (new != old_best)
rte_trace_in(D_ROUTES, new->sender->proto, new, "updated [best]");
rte_trace_in(D_ROUTES, new->sender, new, "updated [best]");
/* Propagate changes */
rte_announce_i(tab, RA_UNDEF, n, NULL, NULL, n->routes, old_best);
@ -2493,7 +2495,7 @@ rte_update_in(struct channel *c, const net_addr *n, rte *new, struct rte_src *sr
/* Required by rte_trace_in() */
new->net = net;
rte_trace_in(D_FILTERS, c->proto, new, "ignored [limit]");
rte_trace_in(D_FILTERS, c, new, "ignored [limit]");
goto drop_update;
}
}

View file

@ -39,7 +39,7 @@ proto_name
pipe_proto:
pipe_proto_start '{'
| pipe_proto proto_item ';'
| pipe_proto channel_item ';'
| pipe_proto channel_item_ ';'
| pipe_proto PEER TABLE rtable ';' { PIPE_CFG->peer = $4; }
;