Skip to content

V
varnishevent
Commit 5353d764 authored by Geoff Simmons's avatar Geoff Simmons
Browse files
Options

implement and test the formatter for %{X}t 

Also refactor strfTIM* to use the %i formatter for the subsecond
value in microseconds (instead of %N for nanoseconds).
Also refactor the varnishevent time formatters to directly use the
string in the log for subseconds, rather than parsing them as doubles,
to avoid inaccuracies due to floating point.
parent 88a06a5e
Hide whitespace changes
Inline Side-by-side
Showing with 100 additions and 92 deletions
src/format.c
View file @ 5353d764
/*- /*-
* Copyright (c) 2013 UPLEX Nils Goroll Systemoptimierung * Copyright (c) 2013-2015 UPLEX Nils Goroll Systemoptimierung
* Copyright (c) 2013 Otto Gmbh & Co KG * Copyright (c) 2013-2015 Otto Gmbh & Co KG
* All rights reserved * All rights reserved
* Use only with permission * Use only with permission
* *
...@@ -418,25 +418,41 @@ FORMAT_r(backend, Bereq) ...@@ -418,25 +418,41 @@ FORMAT_r(backend, Bereq)
FORMAT(client, s, RespStatus) FORMAT(client, s, RespStatus)
FORMAT(backend, s, BerespStatus) FORMAT(backend, s, BerespStatus)
#define FORMAT_tim(ltr, fmt, extra) \ static inline void
void \ format_tim(tx_t *tx, const char *fmt, char **s, size_t *len)
format_##ltr(tx_t *tx, char *name, enum VSL_tag_e tag, \ {
char **s, size_t *len) \ unsigned secs, usecs;
{ \ char *data, *ts;
double t; \ time_t t;
(void) tag; \ struct tm tm;
extra; \
\ data = get_hdr(tx, SLT_Timestamp, "Start");
t = get_tm(tx); \ if (data == NULL)
AN(scratch); \ return;
size_t n = strfTIMlocal(scratch, config.max_reclen, fmt, t); \ ts = get_fld(data, 0);
if (n != 0) { \ if (ts == NULL)
*s = scratch; \ return;
*len = strlen(scratch); \ if (sscanf(ts, "%d.%u", &secs, &usecs) != 2)
} \ return;
} assert(usecs < 1000000);
t = (time_t) secs;
AN(localtime_r(&t, &tm));
AN(scratch);
size_t n = strfTIM(scratch, config.max_reclen, fmt, &tm, usecs);
if (n != 0) {
*s = scratch;
*len = strlen(scratch);
}
}
void
format_t(tx_t *tx, char *name, enum VSL_tag_e tag, char **s, size_t *len)
{
(void) name;
(void) tag;
FORMAT_tim(t, "[%d/%b/%Y:%T %z]", (void) name) format_tim(tx, "[%d/%b/%Y:%T %z]", s, len);
}
#define FORMAT_T(dir, ts) \ #define FORMAT_T(dir, ts) \
void \ void \
...@@ -523,7 +539,13 @@ FORMAT_Xio(backend, i, BereqHeader) ...@@ -523,7 +539,13 @@ FORMAT_Xio(backend, i, BereqHeader)
FORMAT_Xio(client, o, RespHeader) FORMAT_Xio(client, o, RespHeader)
FORMAT_Xio(backend, o, BerespHeader) FORMAT_Xio(backend, o, BerespHeader)
FORMAT_tim(Xt, name, ) void
format_Xt(tx_t *tx, char *name, enum VSL_tag_e tag, char **s, size_t *len)
{
(void) tag;
format_tim(tx, (const char *) name, s, len);
}
#if 0 #if 0
......
src/strfTIM.c
View file @ 5353d764
/*- /*-
* Copyright (c) 2013 UPLEX Nils Goroll Systemoptimierung * Copyright (c) 2013-2015 UPLEX Nils Goroll Systemoptimierung
* Copyright (c) 2013 Otto Gmbh & Co KG * Copyright (c) 2013-2015 Otto Gmbh & Co KG
* All rights reserved * All rights reserved
* Use only with permission * Use only with permission
* *
...@@ -42,23 +42,24 @@ ...@@ -42,23 +42,24 @@
/* /*
* cf. vtim.c/VTIM:timespec in libvarnish * cf. vtim.c/VTIM:timespec in libvarnish
*/ */
static struct timespec static struct timeval
double2timespec(double t) double2timeval(double t)
{ {
struct timespec tv; struct timeval tv;
tv.tv_sec = (time_t)trunc(t); tv.tv_sec = (time_t)trunc(t);
tv.tv_nsec = (int)(1e9 * (t - tv.tv_sec)); tv.tv_usec = (int)(1e6 * (t - tv.tv_sec));
return (tv); return (tv);
} }
size_t size_t
strfTIM(char *s, size_t max, const char *fmt, struct tm *tm, long nsec) strfTIM(char *s, size_t max, const char *fmt, struct tm *tm, unsigned usec)
{ {
struct vsb *vsb = VSB_new(NULL, NULL, max, VSB_FIXEDLEN); struct vsb *vsb = VSB_new(NULL, NULL, max, VSB_FIXEDLEN);
const char *p; const char *p;
size_t n; size_t n;
assert(usec < 1000000);
for (p = fmt; *p; p++) { for (p = fmt; *p; p++) {
if (*p != '%') { if (*p != '%') {
VSB_putc(vsb, *p); VSB_putc(vsb, *p);
...@@ -69,13 +70,13 @@ strfTIM(char *s, size_t max, const char *fmt, struct tm *tm, long nsec) ...@@ -69,13 +70,13 @@ strfTIM(char *s, size_t max, const char *fmt, struct tm *tm, long nsec)
VSB_cat(vsb, "%%"); VSB_cat(vsb, "%%");
continue; continue;
} }
if (*p != 'N') { if (*p != 'i') {
VSB_putc(vsb, '%'); VSB_putc(vsb, '%');
VSB_putc(vsb, *p); VSB_putc(vsb, *p);
continue; continue;
} }
VSB_printf(vsb, "%09ld", nsec); VSB_printf(vsb, "%06u", usec);
} }
VSB_finish(vsb); VSB_finish(vsb);
...@@ -93,11 +94,11 @@ strfTIM(char *s, size_t max, const char *fmt, struct tm *tm, long nsec) ...@@ -93,11 +94,11 @@ strfTIM(char *s, size_t max, const char *fmt, struct tm *tm, long nsec)
size_t \ size_t \
strfTIM##tz(char *s, size_t max, const char *fmt, double t) \ strfTIM##tz(char *s, size_t max, const char *fmt, double t) \
{ \ { \
struct timespec tim = double2timespec(t); \ struct timeval tim = double2timeval(t); \
struct tm tm; \ struct tm tm; \
\ \
AN(tz##time_r((time_t *) &tim.tv_sec, &tm)); \ AN(tz##time_r((time_t *) &tim.tv_sec, &tm)); \
return(strfTIM(s, max, fmt, &tm, tim.tv_nsec)); \ return(strfTIM(s, max, fmt, &tm, tim.tv_usec)); \
} }
strfTIM_tz(local) strfTIM_tz(local)
......
src/strfTIM.h
View file @ 5353d764
...@@ -32,6 +32,7 @@ ...@@ -32,6 +32,7 @@
#include <time.h> #include <time.h>
#include <stddef.h> #include <stddef.h>
size_t strfTIM(char *s, size_t max, const char *fmt, struct tm *tm, long nsec); size_t strfTIM(char *s, size_t max, const char *fmt, struct tm *tm,
unsigned usec);
size_t strfTIMlocal(char *s, size_t max, const char *fmt, double t); size_t strfTIMlocal(char *s, size_t max, const char *fmt, double t);
size_t strfTIMgm(char *s, size_t max, const char *fmt, double t); size_t strfTIMgm(char *s, size_t max, const char *fmt, double t);
src/test/test_format.c
View file @ 5353d764
...@@ -996,7 +996,7 @@ static const char ...@@ -996,7 +996,7 @@ static const char
char afmt[] = char afmt[] =
"%Ec %EC %Ex %EX %Ey %Ey %Od %Oe %OH %OI %Om %OM %OS %Ou %OU %OV %Ow "\ "%Ec %EC %Ex %EX %Ey %Ey %Od %Oe %OH %OI %Om %OM %OS %Ou %OU %OV %Ow "\
"%OW %Oy"; "%OW %Oy";
char subs[] = "%N"; char subs[] = "%i";
struct tm *tm; struct tm *tm;
time_t t = 1427743146; time_t t = 1427743146;
...@@ -1024,8 +1024,8 @@ static const char ...@@ -1024,8 +1024,8 @@ static const char
format_Xt(&tx, subs, SLT__Bogus, &str, &len); format_Xt(&tx, subs, SLT__Bogus, &str, &len);
MAN(str); MAN(str);
/* ms accuracy ... */ /* ms accuracy ... */
VMASSERT(strncmp(str, "529306000", 3) == 0, "'%s' != '529306000'", str); VMASSERT(strcmp(str, "529143") == 0, "'%s' != '529143'", str);
MASSERT(len == 9); MASSERT(len == 6);
return NULL; return NULL;
} }
......
src/test/test_strfTIM.c
View file @ 5353d764
...@@ -39,7 +39,6 @@ ...@@ -39,7 +39,6 @@
#include "../strfTIM.h" #include "../strfTIM.h"
int tests_run = 0; int tests_run = 0;
static char errmsg[BUFSIZ];
static char static char
*test_strfTIM_strftime(void) *test_strfTIM_strftime(void)
...@@ -62,13 +61,11 @@ static char ...@@ -62,13 +61,11 @@ static char
strftime_n = strftime(strftime_s, BUFSIZ, fmt, tm); strftime_n = strftime(strftime_s, BUFSIZ, fmt, tm);
strfTIM_n = strfTIM(strfTIM_s, BUFSIZ, fmt, tm, 0); strfTIM_n = strfTIM(strfTIM_s, BUFSIZ, fmt, tm, 0);
sprintf(errmsg, "strfTIM incorrect return value %zu (expected %zu)", VMASSERT(strfTIM_n == strftime_n, "strfTIM return value %zu (expected %zu)",
strfTIM_n, strftime_n); strfTIM_n, strftime_n);
mu_assert(errmsg, strfTIM_n == strftime_n);
sprintf(errmsg, "strfTIM incorrect result '%s' (expected '%s')", strfTIM_s, VMASSERT(strcmp(strfTIM_s, strftime_s) == 0,
strftime_s); "strfTIM result '%s' (expected '%s')", strfTIM_s, strftime_s);
mu_assert(errmsg, strcmp(strfTIM_s, strftime_s) == 0);
return NULL; return NULL;
} }
...@@ -78,40 +75,36 @@ static char ...@@ -78,40 +75,36 @@ static char
{ {
size_t n; size_t n;
time_t t = 1382804827; time_t t = 1382804827;
long nsec = 112625579; long usec = 112625;
const char *exp = "2013-10-26-18:27:07.112625579"; const char *exp = "2013-10-26-18:27:07.112625";
char s[BUFSIZ]; char s[BUFSIZ];
struct tm *tm; struct tm *tm;
printf("... testing strfTIM %%N conversion specifier\n"); printf("... testing strfTIM %%i conversion specifier\n");
tm = localtime(&t); tm = localtime(&t);
assert(tm != NULL); MAN(tm);
n = strfTIM(s, BUFSIZ, "%F-%T.%N", tm, nsec); n = strfTIM(s, BUFSIZ, "%F-%T.%i", tm, usec);
sprintf(errmsg, "strfTIM incorrect return value %zu (expected %zu)", n, VMASSERT(n == strlen(exp), "strfTIM return value %zu (expected %zu)", n,
strlen(exp)); strlen(exp));
mu_assert(errmsg, n == strlen(exp));
sprintf(errmsg, "strfTIM incorrect result '%s' (expected '%s')", s, exp); VMASSERT(strcmp(s, exp) == 0, "strfTIM result '%s' (expected '%s')", s,
mu_assert(errmsg, strcmp(s, exp) == 0); exp);
n = strfTIM(s, BUFSIZ, "%%N", tm, nsec); n = strfTIM(s, BUFSIZ, "%%i", tm, usec);
sprintf(errmsg, "strfTIM incorrect return value %zu (expected %zu)", n, VMASSERT(n == strlen("%i"), "strfTIM return value %zu (expected %zu)", n,
strlen("%N")); strlen("%i"));
mu_assert(errmsg, n == strlen("%N"));
sprintf(errmsg, "strfTIM incorrect result '%s' (expected '%s')", s, "%N"); VMASSERT(strcmp(s, "%i") == 0, "strfTIM result '%s' (expected '%s')", s,
mu_assert(errmsg, strcmp(s, "%N") == 0); "%i");
n = strfTIM(s, BUFSIZ, "%%%N", tm, nsec); n = strfTIM(s, BUFSIZ, "%%%i", tm, usec);
sprintf(errmsg, "strfTIM incorrect return value %zu (expected %zu)", n, VMASSERT(n == strlen("%112625"), "strfTIM return value %zu (expected %zu)",
strlen("%112625579")); n, strlen("%112625"));
mu_assert(errmsg, n == strlen("%112625579"));
sprintf(errmsg, "strfTIM incorrect result '%s' (expected '%s')", s, VMASSERT(strcmp(s, "%112625") == 0, "strfTIM result '%s' (expected '%s')",
"%112625579"); s, "%112625");
mu_assert(errmsg, strcmp(s, "%112625579") == 0);
return NULL; return NULL;
} }
...@@ -124,23 +117,16 @@ static char ...@@ -124,23 +117,16 @@ static char
printf("... testing strfTIMlocal\n"); printf("... testing strfTIMlocal\n");
n = strfTIMlocal(s, BUFSIZ, "%F-%T.%N", 1382804820.112625579); n = strfTIMlocal(s, BUFSIZ, "%F-%T.%i", 1382804820.112625);
sprintf(exp, "2013-10-26-18:27:0%.9f", 0.112625579); sprintf(exp, "2013-10-26-18:27:0%.6f", 0.112625);
sprintf(errmsg, "strfTIMlocal incorrect return value %zu (expected %zu)", VMASSERT(n == strlen(exp), "strfTIMlocal return value %zu (expected %zu)",
n, strlen(exp)); n, strlen(exp));
mu_assert(errmsg, n == strlen(exp));
/* Not accurate at the last decimal place, due to floating point
/* * precision */
* Don't require equality into the nanosecond range, because that gets s[n - 1] = exp[n - 1] = '\0';
* us into floating point precision issues. Just require equality in VMASSERT(strcmp(s, exp) == 0, "strfTIMlocal result '%s' (expected '%s')",
* the µsec range, by terminating the result string after six decimal s, exp);
* places.
*/
s[strlen(s) - 3] = '\0';
exp[strlen(exp) - 3] = '\0';
sprintf(errmsg, "strfTIMlocal incorrect result '%s' (expected '%s')", s,
exp);
mu_assert(errmsg, strcmp(s, exp) == 0);
return NULL; return NULL;
} }
...@@ -153,17 +139,15 @@ static char ...@@ -153,17 +139,15 @@ static char
printf("... testing strfTIMgm\n"); printf("... testing strfTIMgm\n");
n = strfTIMgm(s, BUFSIZ, "%F-%T.%N", 1382804820.112625579); n = strfTIMgm(s, BUFSIZ, "%F-%T.%i", 1382804820.112625);
sprintf(exp, "2013-10-26-16:27:0%.9f", 0.112625579); sprintf(exp, "2013-10-26-16:27:0%.6f", 0.112625);
sprintf(errmsg, "strfTIMgm incorrect return value %zu (expected %zu)", VMASSERT(n == strlen(exp), "strfTIMgm return value %zu (expected %zu)",
n, strlen(exp)); n, strlen(exp));
mu_assert(errmsg, n == strlen(exp));
/* As above */ /* As above */
s[strlen(s) - 3] = '\0'; s[n - 1] = exp[n - 1] = '\0';
exp[strlen(exp) - 3] = '\0'; VMASSERT(strcmp(s, exp) == 0, "strfTIMgm result '%s' (expected '%s')",
sprintf(errmsg, "strfTIMgm incorrect result '%s' (expected '%s')", s, exp); s, exp);
mu_assert(errmsg, strcmp(s, exp) == 0);
return NULL; return NULL;
} }
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment