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.

diff --git a/Makefile.in b/Makefile.in
index 5a2de437e1ef62101b26fba16d1b7680a1fc5e37..62cb4a47ac5a69896f5a25e35b3d0557ecb07192 100644 (file)
--- 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@
 
 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
 

diff --git a/accesslog.cpp b/accesslog.cpp
index 3e1ebe522ff3f5d462f42659788993b7bffa368f..af53872e6ec03c0d68f83b86e4b9c9f83320eb6d 100644 (file)
--- a/accesslog.cpp
+++ b/accesslog.cpp
@@ -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),

diff --git a/httpinput.cpp b/httpinput.cpp
index 069572753eaef9b04617eb2f1329f8e8e26615f1..50a975cfece1fa70f9535b553fc6c7f322571579 100644 (file)
--- a/httpinput.cpp
+++ b/httpinput.cpp
@@ -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
+++ b/timespec.cpp
@@ -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
+++ 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)