diff --git a/test/e2e/upg_e2e.go b/test/e2e/upg_e2e.go index d2a6a62..8597ba3 100644 --- a/test/e2e/upg_e2e.go +++ b/test/e2e/upg_e2e.go @@ -966,9 +966,59 @@ var _ = ginkgo.Describe("[Reporting]", func() { VTime: 10 * time.Second, } reportCh := f.PFCP.AcquireReportCh() + ts := time.Now() _, err := f.PFCP.EstablishSession(f.Context, 0, sessionCfg.SessionIEs()...) framework.ExpectNoError(err) + quotaInfo := func() (duration int, startTS time.Time, rem float64, handle uint32, foundTrigger, overQuota bool) { + // Quota Validity Time: 10 secs @ 2022/11/16 17:48:27:171, in 9.998 secs, handle 0x00000c03 + out, err := f.VPP.Ctl("show upf session") + framework.ExpectNoError(err, "show upf session") + foundQuota := false + quotaRx := regexp.MustCompile( + `.*Quota\s+Validity\s+Time:\s*(-?\d+)\s+secs\s+@` + + `\s+(\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}):(\d+),` + + `\s+in\s+(\d*.\d*)\s+secs,\s+handle\s+0x([0-9A-Fa-f]+)`) + for _, l := range strings.Split(out, "\n") { + if strings.Contains(l, "Reporting Triggers: 8000 == [QUOTA VALIDITY TIME]") { + foundTrigger = true + continue + } + if strings.Contains(l, "Status: 1 == [OVER QUOTA]") { + overQuota = true + continue + } + m := quotaRx.FindStringSubmatch(l) + if m == nil { + continue + } + duration, err = strconv.Atoi(m[1]) + framework.ExpectNoError(err) + // time.Parse can't parse milliseconds after ':', need d dot + startTS, err = time.Parse("2006/01/02 15:04:05.000", m[2]+"."+m[3]) + framework.ExpectNoError(err) + rem, err = strconv.ParseFloat(m[4], 64) + framework.ExpectNoError(err) + hnd, err := strconv.ParseUint(m[5], 16, 32) + framework.ExpectNoError(err) + handle = uint32(hnd) + foundQuota = true + } + gomega.Expect(foundQuota).To(gomega.BeTrue(), "Quota Validity Time not found in 'show upf session' output") + return duration, startTS, rem, handle, foundTrigger, overQuota + } + + duration, startTS, rem, handle, foundTrigger, overQuota := quotaInfo() + gomega.Expect(duration).To(gomega.Equal(10)) + calcDuration := startTS.Sub(ts) + gomega.Expect(calcDuration).To(gomega.BeNumerically(">=", time.Duration(10))) + gomega.Expect(calcDuration).To(gomega.BeNumerically("<", 13*time.Second)) + gomega.Expect(rem).To(gomega.BeNumerically(">", 7)) + gomega.Expect(rem).To(gomega.BeNumerically("<", 10)) + framework.ExpectNotEqual(handle, uint32(0xffffffff)) + gomega.Expect(foundTrigger).To(gomega.BeTrue()) + gomega.Expect(overQuota).To(gomega.BeFalse()) + var m message.Message gomega.Eventually(reportCh, 12*time.Second, 50*time.Millisecond).Should(gomega.Receive(&m)) framework.ExpectEqual(m.MessageType(), message.MsgTypeSessionReportRequest) @@ -989,6 +1039,19 @@ var _ = ginkgo.Describe("[Reporting]", func() { gomega.Expect(len(urt.Payload)).To(gomega.BeNumerically(">=", 3)) gomega.Expect(urt.Payload[2] & 8).NotTo(gomega.BeZero()) // QUVTI bit is set } + + // Quota Validity Time: 0 secs @ 2022/11/16 18:13:28:101, in -16686224 secs, handle 0xffffffff pid=7608 + duration, newStartTS, rem, handle, foundTrigger, overQuota := quotaInfo() + gomega.Expect(duration).To(gomega.Equal(0)) + diff := newStartTS.Sub(startTS) + if diff < 0 { + diff = -diff + } + gomega.Expect(diff).To(gomega.BeNumerically("<", time.Second)) + gomega.Expect(rem).To(gomega.BeNumerically("<", 0)) + framework.ExpectEqual(handle, uint32(0xffffffff)) + gomega.Expect(foundTrigger).To(gomega.BeFalse()) + gomega.Expect(overQuota).To(gomega.BeTrue()) }) }) diff --git a/upf/upf_pfcp.c b/upf/upf_pfcp.c index 775fd92..bb58478 100644 --- a/upf/upf_pfcp.c +++ b/upf/upf_pfcp.c @@ -2385,8 +2385,9 @@ process_urrs (vlib_main_t * vm, upf_session_t * sess, if (!urr) continue; -#if CLIB_DEBUG > 2 + // TMP: move this under #if f64 unow = unix_time_now (); +#if CLIB_DEBUG > 2 upf_debug ("Monitoring Time: %12.4f - %12.4f : %12.4f Unix: %U - %U : %12.4f", urr->monitoring_time.vlib_time, now, @@ -2461,7 +2462,12 @@ process_urrs (vlib_main_t * vm, upf_session_t * sess, #endif if (PREDICT_FALSE (r & URR_QUOTA_EXHAUSTED)) - urr->status |= URR_OVER_QUOTA; + { + clib_warning ("TMP: %U: SEID Session 0x%016" PRIx64 + "Over volume quota", format_time_float, + NULL, unow, sess->cp_seid); + urr->status |= URR_OVER_QUOTA; + } } if ((urr->methods & PFCP_URR_EVENT) && @@ -2654,6 +2660,11 @@ static const char *urr_trigger_flags[] = { "VOLUME QUOTA", "TIME QUOTA", "ENVELOPE CLOSURE", + "MAC ADDRESSES REPORTING", + "EVENT THRESHOLD", + "EVENT QUOTA", + "IP MULTICAST JOIN LEAVE", + "QUOTA VALIDITY TIME", NULL }; @@ -3002,6 +3013,11 @@ format_pfcp_session (u8 * s, va_list * args) format_urr_time, &urr->time_quota, format_urr_time, &urr->time_threshold); } + if (urr->quota_validity_time.base != 0) + { + s = format (s, " Quota Validity Time: %U\n", + format_urr_time, &urr->quota_validity_time); + } if (urr->monitoring_time.vlib_time != INFINITY) { f64 now = unix_time_now (); diff --git a/upf/upf_pfcp_server.c b/upf/upf_pfcp_server.c index 39d74fd..8a8c464 100644 --- a/upf/upf_pfcp_server.c +++ b/upf/upf_pfcp_server.c @@ -808,6 +808,8 @@ upf_pfcp_session_urr_timer (upf_session_t * sx, f64 now) upf_usage_report_t report; struct rules *active; u32 idx; + // TMP: rm this + f64 unow = unix_time_now (); #if CLIB_DEBUG > 1 f64 vnow = vlib_time_now (gtm->vlib_main); @@ -957,6 +959,12 @@ upf_pfcp_session_urr_timer (upf_session_t * sx, f64 now) upf_pfcp_session_stop_urr_time (&urr->time_quota, now); urr->time_quota.period = 0; urr->status |= URR_OVER_QUOTA; + clib_warning ("TMP: %U: SEID Session 0x%016" PRIx64 + "Over time quota; trigger: %s", + format_time_float, NULL, unow, + sx->cp_seid, + urr->triggers & REPORTING_TRIGGER_TIME_QUOTA ? "true" : + "false"); } if (urr_check (urr->quota_validity_time, now)) { @@ -971,6 +979,12 @@ upf_pfcp_session_urr_timer (upf_session_t * sx, f64 now) upf_pfcp_session_stop_urr_time (&urr->quota_validity_time, now); urr->quota_validity_time.period = 0; urr->status |= URR_OVER_QUOTA; + clib_warning ("TMP: %U: SEID Session 0x%016" PRIx64 + "Over quota validity time; trigger: %s", + format_time_float, NULL, unow, + sx->cp_seid, + urr->triggers & REPORTING_TRIGGER_QUOTA_VALIDITY_TIME ? + "true" : "false"); } if (urr_check (urr->traffic_timer, now))