From b1b81d8f5492e48a60f0ed2930a098747928e5c4 Mon Sep 17 00:00:00 2001 From: "Steinar H. Gunderson" Date: Sat, 2 Apr 2016 01:17:18 +0200 Subject: [PATCH] Fix an issue where access.log would have the wrong timestamp. The refactoring to use monotonic timestamps did not take into account that the timestamps are used for the access log, so it'd contain (roughly) time since boot instead of the actual time of day. Fixed by measuring the offset between the two (although if the clock is wrong at the time of logging, the connection time will be wrong -- as opposed to if the clock is wrong at the time of connect, hard to say which is the better). Reported by Joachim Tingvold. While we are at it, change some of the timespec functions so that we get slightly more precise timing in the logs (it could be about a second off). For cosmetics only. --- Makefile.in | 2 +- accesslog.cpp | 15 +++++++++++---- httpinput.cpp | 19 +------------------ timespec.cpp | 28 ++++++++++++++++++++++++++++ timespec.h | 12 ++++++++++++ 5 files changed, 53 insertions(+), 23 deletions(-) create mode 100644 timespec.cpp create mode 100644 timespec.h diff --git a/Makefile.in b/Makefile.in index 5a2de43..62cb4a4 100644 --- a/Makefile.in +++ b/Makefile.in @@ -7,7 +7,7 @@ CXXFLAGS=-Wall @CXXFLAGS@ @protobuf_CFLAGS@ @libsystemd_CFLAGS@ LDFLAGS=@LDFLAGS@ LIBS=@LIBS@ @protobuf_LIBS@ @libsystemd_LIBS@ -OBJS=main.o client.o server.o stream.o udpstream.o serverpool.o mutexlock.o input.o input_stats.o httpinput.o udpinput.o parse.o config.o acceptor.o stats.o accesslog.o thread.o util.o log.o metacube2.o sa_compare.o state.pb.o +OBJS=main.o client.o server.o stream.o udpstream.o serverpool.o mutexlock.o input.o input_stats.o httpinput.o udpinput.o parse.o config.o acceptor.o stats.o accesslog.o thread.o util.o log.o metacube2.o sa_compare.o timespec.o state.pb.o all: cubemap diff --git a/accesslog.cpp b/accesslog.cpp index 3e1ebe5..af53872 100644 --- a/accesslog.cpp +++ b/accesslog.cpp @@ -8,6 +8,7 @@ #include "client.h" #include "log.h" #include "mutexlock.h" +#include "timespec.h" using namespace std; @@ -53,16 +54,22 @@ void AccessLogThread::do_work() if (logfp != NULL) { // Do the actual writes. - timespec now; - if (clock_gettime(CLOCK_MONOTONIC_COARSE, &now) == -1) { + timespec now_monotonic; + timespec now_realtime; + if (clock_gettime(CLOCK_MONOTONIC_COARSE, &now_monotonic) == -1) { log_perror("clock_gettime(CLOCK_MONOTONIC_COARSE)"); + } else if (clock_gettime(CLOCK_REALTIME, &now_realtime) == -1) { + log_perror("clock_gettime(CLOCK_REALTIME)"); } else { + timespec realtime_offset = clock_diff(now_monotonic, now_realtime); for (size_t i = 0; i < writes.size(); ++i) { + timespec connect_time_realtime = clock_add(writes[i].connect_time, realtime_offset); + timespec time_since_connect = clock_diff(writes[i].connect_time, now_monotonic); fprintf(logfp, "%llu %s %s %d %llu %llu %llu \"%s\" \"%s\"\n", - (long long unsigned)(writes[i].connect_time.tv_sec), + (long long unsigned)(connect_time_realtime.tv_sec), writes[i].remote_addr.c_str(), writes[i].url.c_str(), - int(now.tv_sec - writes[i].connect_time.tv_sec), // Rather coarse. + int(time_since_connect.tv_sec), (long long unsigned)(writes[i].bytes_sent), (long long unsigned)(writes[i].bytes_lost), (long long unsigned)(writes[i].num_loss_events), diff --git a/httpinput.cpp b/httpinput.cpp index 0695727..50a975c 100644 --- a/httpinput.cpp +++ b/httpinput.cpp @@ -24,6 +24,7 @@ #include "serverpool.h" #include "state.pb.h" #include "stream.h" +#include "timespec.h" #include "util.h" #include "version.h" @@ -31,24 +32,6 @@ using namespace std; extern ServerPool *servers; -namespace { - -// Compute b-a. -timespec clock_diff(const timespec &a, const timespec &b) -{ - timespec ret; - ret.tv_sec = b.tv_sec - a.tv_sec; - ret.tv_nsec = b.tv_nsec - a.tv_nsec; - if (ret.tv_nsec < 0) { - ret.tv_sec--; - ret.tv_nsec += 1000000000; - } - assert(ret.tv_nsec >= 0); - return ret; -} - -} // namespace - HTTPInput::HTTPInput(const string &url) : state(NOT_CONNECTED), url(url), diff --git a/timespec.cpp b/timespec.cpp new file mode 100644 index 0000000..66fa26a --- /dev/null +++ b/timespec.cpp @@ -0,0 +1,28 @@ +#include +#include + +#include "timespec.h" + +timespec clock_diff(const timespec &a, const timespec &b) +{ + timespec ret; + ret.tv_sec = b.tv_sec - a.tv_sec; + ret.tv_nsec = b.tv_nsec - a.tv_nsec; + if (ret.tv_nsec < 0) { + ret.tv_sec--; + ret.tv_nsec += 1000000000; + } + assert(ret.tv_nsec >= 0); + return ret; +} + +timespec clock_add(const timespec &a, const timespec &b) +{ + timespec ret; + ret.tv_sec = a.tv_sec + b.tv_sec; + ret.tv_nsec = b.tv_nsec + b.tv_nsec; + + ret.tv_sec += ret.tv_nsec / 1000000000; + ret.tv_nsec %= 1000000000; + return ret; +} diff --git a/timespec.h b/timespec.h new file mode 100644 index 0000000..67dd900 --- /dev/null +++ b/timespec.h @@ -0,0 +1,12 @@ +#ifndef _TIMESPEC_H +#define _TIMESPEC_H 1 + +struct timespec; + +// Compute b-a. +timespec clock_diff(const timespec &a, const timespec &b); + +// Compute a+b. +timespec clock_add(const timespec &a, const timespec &b); + +#endif // !defined(_TIMESPEC_H) -- 2.39.2