Fix an issue where access.log would have the wrong timestamp.
authorSteinar H. Gunderson <sgunderson@bigfoot.com>
Fri, 1 Apr 2016 23:17:18 +0000 (01:17 +0200)
committerSteinar H. Gunderson <sgunderson@bigfoot.com>
Fri, 1 Apr 2016 23:17:18 +0000 (01:17 +0200)
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
accesslog.cpp
httpinput.cpp
timespec.cpp [new file with mode: 0644]
timespec.h [new file with mode: 0644]

index 5a2de43..62cb4a4 100644 (file)
@@ -7,7 +7,7 @@ CXXFLAGS=-Wall @CXXFLAGS@ @protobuf_CFLAGS@ @libsystemd_CFLAGS@
 LDFLAGS=@LDFLAGS@
 LIBS=@LIBS@ @protobuf_LIBS@ @libsystemd_LIBS@
 
 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
 
 
 all: cubemap
 
index 3e1ebe5..af53872 100644 (file)
@@ -8,6 +8,7 @@
 #include "client.h"
 #include "log.h"
 #include "mutexlock.h"
 #include "client.h"
 #include "log.h"
 #include "mutexlock.h"
+#include "timespec.h"
 
 using namespace std;
 
 
 using namespace std;
 
@@ -53,16 +54,22 @@ void AccessLogThread::do_work()
 
                if (logfp != NULL) {
                        // Do the actual writes.
 
                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)");
                                log_perror("clock_gettime(CLOCK_MONOTONIC_COARSE)");
+                       } else if (clock_gettime(CLOCK_REALTIME, &now_realtime) == -1) {
+                               log_perror("clock_gettime(CLOCK_REALTIME)");
                        } else {
                        } else {
+                               timespec realtime_offset = clock_diff(now_monotonic, now_realtime);
                                for (size_t i = 0; i < writes.size(); ++i) {
                                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",
                                        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(),
                                                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),
                                                (long long unsigned)(writes[i].bytes_sent),
                                                (long long unsigned)(writes[i].bytes_lost),
                                                (long long unsigned)(writes[i].num_loss_events),
index 0695727..50a975c 100644 (file)
@@ -24,6 +24,7 @@
 #include "serverpool.h"
 #include "state.pb.h"
 #include "stream.h"
 #include "serverpool.h"
 #include "state.pb.h"
 #include "stream.h"
+#include "timespec.h"
 #include "util.h"
 #include "version.h"
 
 #include "util.h"
 #include "version.h"
 
@@ -31,24 +32,6 @@ using namespace std;
 
 extern ServerPool *servers;
 
 
 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),
 HTTPInput::HTTPInput(const string &url)
        : state(NOT_CONNECTED),
          url(url),
diff --git a/timespec.cpp b/timespec.cpp
new file mode 100644 (file)
index 0000000..66fa26a
--- /dev/null
@@ -0,0 +1,28 @@
+#include <assert.h>
+#include <sys/time.h>
+
+#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 (file)
index 0000000..67dd900
--- /dev/null
@@ -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)