Fix stopping random timers and warn about delayed URR timer events

It's incorrect to try to stop an expired timer:
https://www.mail-archive.com/[email protected]/msg10495.html
... but that was happening with PFCP message timers. This could
possibly lead to stopping random timers that are started in the
same pfcp_process() loop iterations.
Also, print warnings when URR events are delayed by more than 5s.
This will make it possible to detect further URR timer problems
without complicated examination of PFCP PCAPs.

upf/upf_pfcp_server.c

@@ -39,6 +39,8 @@
 #define TW_SECS_PER_CLOCK 10e-3	/* 10ms */
 #define TW_CLOCKS_PER_SECOND (1 / TW_SECS_PER_CLOCK)
 
+#define LATE_TIMER_WARNING_THRESHOLD 5
+
 #if CLIB_DEBUG > 1
 #define upf_debug clib_warning
 #define urr_debug_out(format, args...)				\
@@ -810,6 +812,12 @@ upf_pfcp_session_urr_timer (upf_session_t * sx, f64 now)
 #define urr_check(V, NOW)				\
     (((V).base != 0) && ((V).period != 0) &&		\
      ((V).expected != 0) && (V).expected < (NOW))
+#define urr_check_late(V, NOW)					\
+    do { 							\
+      if ((V).expected < (NOW) - LATE_TIMER_WARNING_THRESHOLD)	\
+	clib_warning("WARNING: timer late by %.4f seconds: "#V, \
+		     (NOW) - (V).expected);			\
+    } while (0)
 
 #define URR_COND_TIME(t, time)			\
     (t).period != 0 ? time : 0
@@ -849,6 +857,7 @@ upf_pfcp_session_urr_timer (upf_session_t * sx, f64 now)
 
     if (urr_check (urr->measurement_period, now))
       {
+	urr_check_late (urr->measurement_period, now);
 	if (urr->triggers & REPORTING_TRIGGER_PERIODIC_REPORTING)
 	  {
 	    trigger |= USAGE_REPORT_TRIGGER_PERIODIC_REPORTING;
@@ -884,6 +893,7 @@ upf_pfcp_session_urr_timer (upf_session_t * sx, f64 now)
       }
     if (urr_check (urr->time_threshold, now))
       {
+	urr_check_late (urr->time_threshold, now);
 	if (urr->triggers & REPORTING_TRIGGER_TIME_THRESHOLD)
 	  {
 	    trigger |= USAGE_REPORT_TRIGGER_TIME_THRESHOLD;
@@ -895,6 +905,7 @@ upf_pfcp_session_urr_timer (upf_session_t * sx, f64 now)
       }
     if (urr_check (urr->time_quota, now))
       {
+	urr_check_late (urr->time_quota, now);
 	if (urr->triggers & REPORTING_TRIGGER_TIME_QUOTA)
 	  {
 	    trigger |= USAGE_REPORT_TRIGGER_TIME_QUOTA;
@@ -907,6 +918,7 @@ upf_pfcp_session_urr_timer (upf_session_t * sx, f64 now)
       }
     if (urr_check (urr->quota_validity_time, now))
       {
+	urr_check_late (urr->quota_validity_time, now);
 	if (urr->triggers & REPORTING_TRIGGER_QUOTA_VALIDITY_TIME)
 	  {
 	    trigger |= USAGE_REPORT_TRIGGER_QUOTA_VALIDITY_TIME;
@@ -924,6 +936,8 @@ upf_pfcp_session_urr_timer (upf_session_t * sx, f64 now)
 	upf_urr_traffic_t **expired = NULL;
 	upf_urr_traffic_t *tt = NULL;
 
+	urr_check_late (urr->traffic_timer, now);
+
 	pool_foreach (tt, urr->traffic)
 	{
 	  if (tt->first_seen + 60 < now)
@@ -1062,10 +1076,18 @@ void upf_pfcp_server_stop_msg_timer (pfcp_msg_t * msg)
   vec_foreach (exp_id, psm->expired)
   {
     if (*exp_id == id_t1 || *exp_id == id_resp)
-      *exp_id = ~0;
+      {
+	msg->timer = ~0;
+	*exp_id = ~0;
+      }
   }
 
-  TW (tw_timer_stop) (&psm->timer, msg->timer);
+  /*
+   * Don't call tw_timer_stop() on expired timer handles as they're invalid
+   * Ref: https://www.mail-archive.com/[email protected]/msg10495.html
+   */
+  if (msg->timer != ~0)
+    TW (tw_timer_stop) (&psm->timer, msg->timer);
   msg->timer = ~0;
 }