diff --git a/isisd/isis_circuit.c b/isisd/isis_circuit.c index a49994a78b..c4d2ba76b8 100644 --- a/isisd/isis_circuit.c +++ b/isisd/isis_circuit.c @@ -785,6 +785,8 @@ isis_circuit_down (struct isis_circuit *circuit) THREAD_TIMER_OFF (circuit->u.bc.t_run_dr[1]); THREAD_TIMER_OFF (circuit->u.bc.t_refresh_pseudo_lsp[0]); THREAD_TIMER_OFF (circuit->u.bc.t_refresh_pseudo_lsp[1]); + circuit->lsp_regenerate_pending[0] = 0; + circuit->lsp_regenerate_pending[1] = 0; } else if (circuit->circ_type == CIRCUIT_T_P2P) { diff --git a/isisd/isis_events.c b/isisd/isis_events.c index 3887b7c5a2..79e5ab379d 100644 --- a/isisd/isis_events.c +++ b/isisd/isis_events.c @@ -110,7 +110,10 @@ area_resign_level (struct isis_area *area, int level) } #endif /* HAVE_IPV6 */ + sched_debug("ISIS (%s): Resigned from L%d - canceling LSP regeneration timer.", + area->area_tag, level); THREAD_TIMER_OFF (area->t_lsp_refresh[level - 1]); + area->lsp_regenerate_pending[level - 1] = 0; } void @@ -245,6 +248,7 @@ circuit_resign_level (struct isis_circuit *circuit, int level) THREAD_TIMER_OFF (circuit->u.bc.t_send_lan_hello[idx]); THREAD_TIMER_OFF (circuit->u.bc.t_run_dr[idx]); THREAD_TIMER_OFF (circuit->u.bc.t_refresh_pseudo_lsp[idx]); + circuit->lsp_regenerate_pending[idx] = 0; circuit->u.bc.run_dr_elect[idx] = 0; list_delete (circuit->u.bc.lan_neighs[idx]); circuit->u.bc.lan_neighs[idx] = NULL; diff --git a/isisd/isis_lsp.c b/isisd/isis_lsp.c index 30e4fc49ba..725288e311 100644 --- a/isisd/isis_lsp.c +++ b/isisd/isis_lsp.c @@ -1681,10 +1681,13 @@ lsp_generate (struct isis_area *area, int level) lsp_build (newlsp, area); /* time to calculate our checksum */ lsp_seqnum_update (newlsp); + newlsp->last_generated = time(NULL); lsp_set_all_srmflags (newlsp); refresh_time = lsp_refresh_time (newlsp, rem_lifetime); + THREAD_TIMER_OFF (area->t_lsp_refresh[level - 1]); + area->lsp_regenerate_pending[level - 1] = 0; if (level == IS_LEVEL_1) THREAD_TIMER_ON (master, area->t_lsp_refresh[level - 1], lsp_l1_refresh, area, refresh_time); @@ -1704,6 +1707,8 @@ lsp_generate (struct isis_area *area, int level) ntohs (newlsp->lsp_header->rem_lifetime), refresh_time); } + sched_debug("ISIS (%s): Built L%d LSP. Set triggered regenerate to non-pending.", + area->area_tag, level); return ISIS_OK; } @@ -1766,6 +1771,7 @@ lsp_regenerate (struct isis_area *area, int level) else if (level == IS_LEVEL_2) THREAD_TIMER_ON (master, area->t_lsp_refresh[level - 1], lsp_l2_refresh, area, refresh_time); + area->lsp_regenerate_pending[level - 1] = 0; if (isis->debugs & DEBUG_UPDATE_PACKETS) { @@ -1779,6 +1785,8 @@ lsp_regenerate (struct isis_area *area, int level) ntohs (lsp->lsp_header->rem_lifetime), refresh_time); } + sched_debug("ISIS (%s): Rebuilt L%d LSP. Set triggered regenerate to non-pending.", + area->area_tag, level); return ISIS_OK; } @@ -1800,6 +1808,7 @@ lsp_l1_refresh (struct thread *thread) if ((area->is_type & IS_LEVEL_1) == 0) return ISIS_ERROR; + sched_debug("ISIS (%s): LSP L1 refresh timer expired. Refreshing LSP...", area->area_tag); return lsp_regenerate (area, IS_LEVEL_1); } @@ -1817,6 +1826,7 @@ lsp_l2_refresh (struct thread *thread) if ((area->is_type & IS_LEVEL_2) == 0) return ISIS_ERROR; + sched_debug("ISIS (%s): LSP L2 refresh timer expired. Refreshing LSP...", area->area_tag); return lsp_regenerate (area, IS_LEVEL_2); } @@ -1826,6 +1836,7 @@ lsp_regenerate_schedule (struct isis_area *area, int level, int all_pseudo) struct isis_lsp *lsp; u_char id[ISIS_SYS_ID_LEN + 2]; time_t now, diff; + long timeout; struct listnode *cnode; struct isis_circuit *circuit; int lvl; @@ -1833,6 +1844,9 @@ lsp_regenerate_schedule (struct isis_area *area, int level, int all_pseudo) if (area == NULL) return ISIS_ERROR; + sched_debug("ISIS (%s): Scheduling regeneration of %s LSPs, %sincluding PSNs", + area->area_tag, circuit_t2string(level), all_pseudo ? "" : "not "); + memcpy (id, isis->sysid, ISIS_SYS_ID_LEN); LSP_PSEUDO_ID (id) = LSP_FRAGMENT (id) = 0; now = time (NULL); @@ -1842,29 +1856,38 @@ lsp_regenerate_schedule (struct isis_area *area, int level, int all_pseudo) if (!((level & lvl) && (area->is_type & lvl))) continue; + sched_debug("ISIS (%s): Checking whether L%d needs to be scheduled", + area->area_tag, lvl); + if (area->lsp_regenerate_pending[lvl - 1]) - continue; + { + struct timeval remain = thread_timer_remain(area->t_lsp_refresh[lvl - 1]); + sched_debug("ISIS (%s): Regeneration is already pending, nothing todo." + " (Due in %lld.%03lld seconds)", area->area_tag, + (long long)remain.tv_sec, (long long)remain.tv_usec / 1000); + continue; + } lsp = lsp_search (id, area->lspdb[lvl - 1]); if (!lsp) - continue; + { + sched_debug("ISIS (%s): We do not have any LSPs to regenerate, nothing todo.", + area->area_tag); + continue; + } /* * Throttle avoidance */ + sched_debug("ISIS (%s): Will schedule regen timer. Last run was: %lld, Now is: %lld", + area->area_tag, (long long)lsp->last_generated, (long long)now); THREAD_TIMER_OFF (area->t_lsp_refresh[lvl - 1]); diff = now - lsp->last_generated; if (diff < area->lsp_gen_interval[lvl - 1]) { - area->lsp_regenerate_pending[lvl - 1] = 1; - if (lvl == IS_LEVEL_1) - THREAD_TIMER_ON (master, area->t_lsp_refresh[lvl - 1], - lsp_l1_refresh, area, - area->lsp_gen_interval[lvl - 1] - diff); - else if (lvl == IS_LEVEL_2) - THREAD_TIMER_ON (master, area->t_lsp_refresh[lvl - 1], - lsp_l2_refresh, area, - area->lsp_gen_interval[lvl - 1] - diff); + timeout = 1000 * (area->lsp_gen_interval[lvl - 1] - diff); + sched_debug("ISIS (%s): Scheduling in %ld ms to match configured lsp_gen_interval", + area->area_tag, timeout); } else { @@ -1873,13 +1896,21 @@ lsp_regenerate_schedule (struct isis_area *area, int level, int all_pseudo) * directly. However if the lsp_regenerate call is queued for * later execution it works. */ - area->lsp_regenerate_pending[lvl - 1] = 1; - if (lvl == IS_LEVEL_1) - THREAD_TIMER_ON (master, area->t_lsp_refresh[lvl - 1], - lsp_l1_refresh, area, 0); - else if (lvl == IS_LEVEL_2) - THREAD_TIMER_ON (master, area->t_lsp_refresh[lvl - 1], - lsp_l2_refresh, area, 0); + timeout = 100; + sched_debug("ISIS (%s): Last generation was more than lsp_gen_interval ago." + " Scheduling for execution in %ld ms.", area->area_tag, timeout); + } + + area->lsp_regenerate_pending[lvl - 1] = 1; + if (lvl == IS_LEVEL_1) + { + THREAD_TIMER_MSEC_ON(master, area->t_lsp_refresh[lvl - 1], + lsp_l1_refresh, area, timeout); + } + else if (lvl == IS_LEVEL_2) + { + THREAD_TIMER_MSEC_ON(master, area->t_lsp_refresh[lvl - 1], + lsp_l2_refresh, area, timeout); } } @@ -2231,13 +2262,18 @@ lsp_regenerate_schedule_pseudo (struct isis_circuit *circuit, int level) struct isis_lsp *lsp; u_char lsp_id[ISIS_SYS_ID_LEN + 2]; time_t now, diff; + long timeout; int lvl; + struct isis_area *area = circuit->area; if (circuit == NULL || circuit->circ_type != CIRCUIT_T_BROADCAST || circuit->state != C_STATE_UP) return ISIS_OK; + sched_debug("ISIS (%s): Scheduling regeneration of %s pseudo LSP for interface %s", + area->area_tag, circuit_t2string(level), circuit->interface->name); + memcpy (lsp_id, isis->sysid, ISIS_SYS_ID_LEN); LSP_PSEUDO_ID (lsp_id) = circuit->circuit_id; LSP_FRAGMENT (lsp_id) = 0; @@ -2245,39 +2281,74 @@ lsp_regenerate_schedule_pseudo (struct isis_circuit *circuit, int level) for (lvl = IS_LEVEL_1; lvl <= IS_LEVEL_2; lvl++) { - if (!((level & lvl) && (circuit->is_type & lvl))) - continue; + sched_debug("ISIS (%s): Checking whether L%d pseudo LSP needs to be scheduled", + area->area_tag, lvl); - if (circuit->u.bc.is_dr[lvl - 1] == 0 || - circuit->lsp_regenerate_pending[lvl - 1]) - continue; + if (!((level & lvl) && (circuit->is_type & lvl))) + { + sched_debug("ISIS (%s): Level is not active on circuit", + area->area_tag); + continue; + } + + if (circuit->u.bc.is_dr[lvl - 1] == 0) + { + sched_debug("ISIS (%s): This IS is not DR, nothing to do.", + area->area_tag); + continue; + } + + if (circuit->lsp_regenerate_pending[lvl - 1]) + { + struct timeval remain = + thread_timer_remain(circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1]); + sched_debug("ISIS (%s): Regenerate is already pending, nothing todo." + " (Due in %lld.%03lld seconds)", area->area_tag, + (long long)remain.tv_sec, (long long)remain.tv_usec/1000); + continue; + } lsp = lsp_search (lsp_id, circuit->area->lspdb[lvl - 1]); if (!lsp) - continue; + { + sched_debug("ISIS (%s): Pseudonode LSP does not exist yet, nothing to regenerate.", + area->area_tag); + continue; + } /* * Throttle avoidance */ + sched_debug("ISIS (%s): Will schedule PSN regen timer. Last run was: %lld, Now is: %lld", + area->area_tag, (long long)lsp->last_generated, (long long) now); THREAD_TIMER_OFF (circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1]); diff = now - lsp->last_generated; if (diff < circuit->area->lsp_gen_interval[lvl - 1]) { - circuit->lsp_regenerate_pending[lvl - 1] = 1; - if (lvl == IS_LEVEL_1) - THREAD_TIMER_ON (master, - circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1], - lsp_l1_refresh_pseudo, circuit, - circuit->area->lsp_gen_interval[lvl - 1] - diff); - else if (lvl == IS_LEVEL_2) - THREAD_TIMER_ON (master, - circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1], - lsp_l2_refresh_pseudo, circuit, - circuit->area->lsp_gen_interval[lvl - 1] - diff); + timeout = 1000 * (circuit->area->lsp_gen_interval[lvl - 1] - diff); + sched_debug("ISIS (%s): Sechduling in %ld ms to match configured lsp_gen_interval", + area->area_tag, timeout); } else { - lsp_regenerate_pseudo (circuit, lvl); + timeout = 100; + sched_debug("ISIS (%s): Last generation was more than lsp_gen_interval ago." + " Scheduling for execution in %ld ms.", area->area_tag, timeout); + } + + circuit->lsp_regenerate_pending[lvl - 1] = 1; + + if (lvl == IS_LEVEL_1) + { + THREAD_TIMER_MSEC_ON(master, + circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1], + lsp_l1_refresh_pseudo, circuit, timeout); + } + else if (lvl == IS_LEVEL_2) + { + THREAD_TIMER_MSEC_ON(master, + circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1], + lsp_l2_refresh_pseudo, circuit, timeout); } } diff --git a/isisd/isisd.c b/isisd/isisd.c index c05f94c755..500d2b24cf 100644 --- a/isisd/isisd.c +++ b/isisd/isisd.c @@ -774,6 +774,8 @@ print_debug (struct vty *vty, int flags, int onoff) vty_out (vty, "IS-IS Packet dump debugging is %s%s", onoffs, VTY_NEWLINE); if (flags & DEBUG_LSP_GEN) vty_out (vty, "IS-IS LSP generation debugging is %s%s", onoffs, VTY_NEWLINE); + if (flags & DEBUG_LSP_SCHED) + vty_out (vty, "IS-IS LSP scheduling debugging is %s%s", onoffs, VTY_NEWLINE); } DEFUN (show_debugging, @@ -866,6 +868,11 @@ config_write_debug (struct vty *vty) vty_out (vty, "debug isis lsp-gen%s", VTY_NEWLINE); write++; } + if (flags & DEBUG_LSP_SCHED) + { + vty_out (vty, "debug isis lsp-sched%s", VTY_NEWLINE); + write++; + } return write; } @@ -1208,6 +1215,32 @@ DEFUN (no_debug_isis_lsp_gen, return CMD_SUCCESS; } +DEFUN (debug_isis_lsp_sched, + debug_isis_lsp_sched_cmd, + "debug isis lsp-sched", + DEBUG_STR + "IS-IS information\n" + "IS-IS scheduling of LSP generation\n") +{ + isis->debugs |= DEBUG_LSP_SCHED; + print_debug (vty, DEBUG_LSP_SCHED, 1); + + return CMD_SUCCESS; +} + +DEFUN (no_debug_isis_lsp_sched, + no_debug_isis_lsp_sched_cmd, + "no debug isis lsp-gen", + UNDEBUG_STR + "IS-IS information\n" + "IS-IS scheduling of LSP generation\n") +{ + isis->debugs &= ~DEBUG_LSP_SCHED; + print_debug (vty, DEBUG_LSP_SCHED, 0); + + return CMD_SUCCESS; +} + DEFUN (show_hostname, show_hostname_cmd, "show isis hostname", @@ -3296,6 +3329,8 @@ isis_init () install_element (ENABLE_NODE, &no_debug_isis_packet_dump_cmd); install_element (ENABLE_NODE, &debug_isis_lsp_gen_cmd); install_element (ENABLE_NODE, &no_debug_isis_lsp_gen_cmd); + install_element (ENABLE_NODE, &debug_isis_lsp_sched_cmd); + install_element (ENABLE_NODE, &no_debug_isis_lsp_sched_cmd); install_element (CONFIG_NODE, &debug_isis_adj_cmd); install_element (CONFIG_NODE, &no_debug_isis_adj_cmd); @@ -3323,6 +3358,8 @@ isis_init () install_element (CONFIG_NODE, &no_debug_isis_packet_dump_cmd); install_element (CONFIG_NODE, &debug_isis_lsp_gen_cmd); install_element (CONFIG_NODE, &no_debug_isis_lsp_gen_cmd); + install_element (CONFIG_NODE, &debug_isis_lsp_sched_cmd); + install_element (CONFIG_NODE, &no_debug_isis_lsp_sched_cmd); install_element (CONFIG_NODE, &router_isis_cmd); install_element (CONFIG_NODE, &no_router_isis_cmd); diff --git a/isisd/isisd.h b/isisd/isisd.h index 9a50c2db5f..35d27dbe86 100644 --- a/isisd/isisd.h +++ b/isisd/isisd.h @@ -99,6 +99,17 @@ struct isis_area struct flags flags; struct thread *t_tick; /* LSP walker */ struct thread *t_lsp_refresh[ISIS_LEVELS]; + /* t_lsp_refresh is used in two ways: + * a) regular refresh of LSPs + * b) (possibly throttled) updates to LSPs + * + * The lsp_regenerate_pending flag tracks whether the timer is active + * for the a) or the b) case. + * + * It is of utmost importance to clear this flag when the timer is + * rescheduled for normal refresh, because otherwise, updates will + * be delayed until the next regular refresh. + */ int lsp_regenerate_pending[ISIS_LEVELS]; /* @@ -169,6 +180,7 @@ extern struct thread_master *master; #define DEBUG_ZEBRA (1<<11) #define DEBUG_PACKET_DUMP (1<<12) #define DEBUG_LSP_GEN (1<<13) +#define DEBUG_LSP_SCHED (1<<14) #define lsp_debug(...) \ do \ @@ -178,4 +190,12 @@ extern struct thread_master *master; } \ while (0) +#define sched_debug(...) \ + do \ + { \ + if (isis->debugs & DEBUG_LSP_SCHED) \ + zlog_debug(__VA_ARGS__); \ + } \ + while (0) + #endif /* ISISD_H */