Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[WiP] Fix quota validity time info in "show upf session" output #308

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
Open

[WiP] Fix quota validity time info in "show upf session" output #308

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
63 changes: 63 additions & 0 deletions test/e2e/upg_e2e.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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())
})
})

Expand Down
20 changes: 18 additions & 2 deletions upf/upf_pfcp.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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) &&
Expand Down Expand Up @@ -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
};

Expand Down Expand Up @@ -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 ();
Expand Down
14 changes: 14 additions & 0 deletions upf/upf_pfcp_server.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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))
{
Expand All @@ -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))
Expand Down