get_server_time.cc revision bbcdd45c55eb7c4641ab97aef9889b0fc828e7d3 
1// Copyright (c) 2012 The Chromium Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5// This is a small utility that snarfs the server time from the
6// response headers of an http/https HEAD request and compares it to
7// the local time.
8//
9// TODO(akalin): Also snarf the server time from the TLS handshake, if
10// any (http://crbug.com/146090).
11
12#include <cstdio>
13#include <cstdlib>
14#include <string>
15
16#include "base/at_exit.h"
17#include "base/basictypes.h"
18#include "base/command_line.h"
19#include "base/compiler_specific.h"
20#include "base/format_macros.h"
21#include "base/i18n/time_formatting.h"
22#include "base/json/json_writer.h"
23#include "base/logging.h"
24#include "base/memory/ref_counted.h"
25#include "base/memory/scoped_ptr.h"
26#include "base/message_loop/message_loop.h"
27#include "base/single_thread_task_runner.h"
28#include "base/strings/string_number_conversions.h"
29#include "base/strings/utf_string_conversions.h"
30#include "base/time/time.h"
31#include "base/values.h"
32#include "build/build_config.h"
33#include "net/base/net_errors.h"
34#include "net/base/net_log.h"
35#include "net/http/http_response_headers.h"
36#include "net/url_request/url_fetcher.h"
37#include "net/url_request/url_fetcher_delegate.h"
38#include "net/url_request/url_request_context.h"
39#include "net/url_request/url_request_context_builder.h"
40#include "net/url_request/url_request_context_getter.h"
41#include "net/url_request/url_request_status.h"
42#include "url/gurl.h"
43
44#if defined(OS_MACOSX)
45#include "base/mac/scoped_nsautorelease_pool.h"
46#elif defined(OS_LINUX)
47#include "net/proxy/proxy_config.h"
48#include "net/proxy/proxy_config_service_fixed.h"
49#endif
50
51namespace {
52
53// base::TimeTicks::Now() is documented to have a resolution of
54// ~1-15ms.
55const int64 kTicksResolutionMs = 15;
56
57// For the sources that are supported (HTTP date headers, TLS
58// handshake), the resolution of the server time is 1 second.
59const int64 kServerTimeResolutionMs = 1000;
60
61// Assume base::Time::Now() has the same resolution as
62// base::TimeTicks::Now().
63//
64// TODO(akalin): Figure out the real resolution.
65const int64 kTimeResolutionMs = kTicksResolutionMs;
66
67// Simply quits the current message loop when finished.  Used to make
68// URLFetcher synchronous.
69class QuitDelegate : public net::URLFetcherDelegate {
70 public:
71  QuitDelegate() {}
72
73  virtual ~QuitDelegate() {}
74
75  // net::URLFetcherDelegate implementation.
76  virtual void OnURLFetchComplete(const net::URLFetcher* source) OVERRIDE {
77    base::MessageLoop::current()->Quit();
78  }
79
80  virtual void OnURLFetchDownloadProgress(
81      const net::URLFetcher* source,
82      int64 current, int64 total) OVERRIDE {
83    NOTREACHED();
84  }
85
86  virtual void OnURLFetchDownloadData(
87      const net::URLFetcher* source,
88      scoped_ptr<std::string> download_data) OVERRIDE{
89    NOTREACHED();
90  }
91
92  virtual bool ShouldSendDownloadData() OVERRIDE {
93    NOTREACHED();
94    return false;
95  }
96
97  virtual void OnURLFetchUploadProgress(const net::URLFetcher* source,
98                                        int64 current, int64 total) OVERRIDE {
99    NOTREACHED();
100  }
101
102 private:
103  DISALLOW_COPY_AND_ASSIGN(QuitDelegate);
104};
105
106// NetLog::ThreadSafeObserver implementation that simply prints events
107// to the logs.
108class PrintingLogObserver : public net::NetLog::ThreadSafeObserver {
109 public:
110  PrintingLogObserver() {}
111
112  virtual ~PrintingLogObserver() {
113    // This is guaranteed to be safe as this program is single threaded.
114    net_log()->RemoveThreadSafeObserver(this);
115  }
116
117  // NetLog::ThreadSafeObserver implementation:
118  virtual void OnAddEntry(const net::NetLog::Entry& entry) OVERRIDE {
119    // The log level of the entry is unknown, so just assume it maps
120    // to VLOG(1).
121    if (!VLOG_IS_ON(1))
122      return;
123
124    const char* const source_type =
125        net::NetLog::SourceTypeToString(entry.source().type);
126    const char* const event_type =
127        net::NetLog::EventTypeToString(entry.type());
128    const char* const event_phase =
129        net::NetLog::EventPhaseToString(entry.phase());
130    scoped_ptr<base::Value> params(entry.ParametersToValue());
131    std::string params_str;
132    if (params.get()) {
133      base::JSONWriter::Write(params.get(), &params_str);
134      params_str.insert(0, ": ");
135    }
136
137    VLOG(1) << source_type << "(" << entry.source().id << "): "
138            << event_type << ": " << event_phase << params_str;
139  }
140
141 private:
142  DISALLOW_COPY_AND_ASSIGN(PrintingLogObserver);
143};
144
145// Builds a URLRequestContext assuming there's only a single loop.
146scoped_ptr<net::URLRequestContext>
147BuildURLRequestContext(net::NetLog* net_log) {
148  net::URLRequestContextBuilder builder;
149#if defined(OS_LINUX)
150  // On Linux, use a fixed ProxyConfigService, since the default one
151  // depends on glib.
152  //
153  // TODO(akalin): Remove this once http://crbug.com/146421 is fixed.
154  builder.set_proxy_config_service(
155      new net::ProxyConfigServiceFixed(net::ProxyConfig()));
156#endif
157  scoped_ptr<net::URLRequestContext> context(builder.Build());
158  context->set_net_log(net_log);
159  return context.Pass();
160}
161
162class SingleThreadRequestContextGetter : public net::URLRequestContextGetter {
163 public:
164  // Since there's only a single thread, there's no need to worry
165  // about when |context_| gets created.
166  SingleThreadRequestContextGetter(
167      net::NetLog* net_log,
168      const scoped_refptr<base::SingleThreadTaskRunner>& main_task_runner)
169      : context_(BuildURLRequestContext(net_log)),
170        main_task_runner_(main_task_runner) {}
171
172  virtual net::URLRequestContext* GetURLRequestContext() OVERRIDE {
173    return context_.get();
174  }
175
176  virtual scoped_refptr<base::SingleThreadTaskRunner>
177  GetNetworkTaskRunner() const OVERRIDE {
178    return main_task_runner_;
179  }
180
181 private:
182  virtual ~SingleThreadRequestContextGetter() {}
183
184  const scoped_ptr<net::URLRequestContext> context_;
185  const scoped_refptr<base::SingleThreadTaskRunner> main_task_runner_;
186};
187
188// Assuming that the time |server_time| was received from a server,
189// that the request for the server was started on |start_ticks|, and
190// that it ended on |end_ticks|, fills |server_now| with an estimate
191// of the current time and |server_now_uncertainty| with a
192// conservative estimate of the uncertainty.
193void EstimateServerTimeNow(base::Time server_time,
194                           base::TimeTicks start_ticks,
195                           base::TimeTicks end_ticks,
196                           base::Time* server_now,
197                           base::TimeDelta* server_now_uncertainty) {
198  const base::TimeDelta delta_ticks = end_ticks - start_ticks;
199  const base::TimeTicks mid_ticks = start_ticks + delta_ticks / 2;
200  const base::TimeDelta estimated_elapsed = base::TimeTicks::Now() - mid_ticks;
201
202  *server_now = server_time + estimated_elapsed;
203
204  *server_now_uncertainty =
205      base::TimeDelta::FromMilliseconds(kServerTimeResolutionMs) +
206      delta_ticks + 3 * base::TimeDelta::FromMilliseconds(kTicksResolutionMs);
207}
208
209// Assuming that the time of the server is |server_now| with
210// uncertainty |server_now_uncertainty| and that the local time is
211// |now|, fills |skew| with the skew of the local clock (i.e., add
212// |*skew| to a client time to get a server time) and
213// |skew_uncertainty| with a conservative estimate of the uncertainty.
214void EstimateSkew(base::Time server_now,
215                  base::TimeDelta server_now_uncertainty,
216                  base::Time now,
217                  base::TimeDelta now_uncertainty,
218                  base::TimeDelta* skew,
219                  base::TimeDelta* skew_uncertainty) {
220  *skew = server_now - now;
221  *skew_uncertainty = server_now_uncertainty + now_uncertainty;
222}
223
224}  // namespace
225
226int main(int argc, char* argv[]) {
227#if defined(OS_MACOSX)
228  base::mac::ScopedNSAutoreleasePool pool;
229#endif
230
231  base::AtExitManager exit_manager;
232  CommandLine::Init(argc, argv);
233  logging::LoggingSettings settings;
234  settings.logging_dest = logging::LOG_TO_SYSTEM_DEBUG_LOG;
235  logging::InitLogging(settings);
236
237  const CommandLine& parsed_command_line = *CommandLine::ForCurrentProcess();
238  GURL url(parsed_command_line.GetSwitchValueASCII("url"));
239  if (!url.is_valid() ||
240      (url.scheme() != "http" && url.scheme() != "https")) {
241    std::fprintf(
242        stderr,
243        "Usage: %s --url=[http|https]://www.example.com [--v=[1|2]]\n",
244        argv[0]);
245    return EXIT_FAILURE;
246  }
247
248  base::MessageLoopForIO main_loop;
249
250  // NOTE: A NetworkChangeNotifier could be instantiated here, but
251  // that interferes with the request that will be sent; some
252  // implementations always send out an OnIPAddressChanged() message,
253  // which causes the DNS resolution to abort.  It's simpler to just
254  // not instantiate one, since only a single request is sent anyway.
255
256  // The declaration order for net_log and printing_log_observer is
257  // important. The destructor of PrintingLogObserver removes itself
258  // from net_log, so net_log must be available for entire lifetime of
259  // printing_log_observer.
260  net::NetLog net_log;
261  PrintingLogObserver printing_log_observer;
262  net_log.AddThreadSafeObserver(&printing_log_observer, net::NetLog::LOG_ALL);
263  scoped_refptr<SingleThreadRequestContextGetter> context_getter(
264      new SingleThreadRequestContextGetter(&net_log,
265                                           main_loop.message_loop_proxy()));
266
267  QuitDelegate delegate;
268  scoped_ptr<net::URLFetcher> fetcher(
269      net::URLFetcher::Create(url, net::URLFetcher::HEAD, &delegate));
270  fetcher->SetRequestContext(context_getter.get());
271
272  const base::Time start_time = base::Time::Now();
273  const base::TimeTicks start_ticks = base::TimeTicks::Now();
274
275  fetcher->Start();
276  std::printf(
277      "Request started at %s (ticks = %" PRId64 ")\n",
278      UTF16ToUTF8(base::TimeFormatFriendlyDateAndTime(start_time)).c_str(),
279      start_ticks.ToInternalValue());
280
281  // |delegate| quits |main_loop| when the request is done.
282  main_loop.Run();
283
284  const base::Time end_time = base::Time::Now();
285  const base::TimeTicks end_ticks = base::TimeTicks::Now();
286
287  std::printf(
288      "Request ended at %s (ticks = %" PRId64 ")\n",
289      UTF16ToUTF8(base::TimeFormatFriendlyDateAndTime(end_time)).c_str(),
290      end_ticks.ToInternalValue());
291
292  const int64 delta_ticks_internal =
293      end_ticks.ToInternalValue() - start_ticks.ToInternalValue();
294  const base::TimeDelta delta_ticks = end_ticks - start_ticks;
295
296  std::printf(
297      "Request took %" PRId64 " ticks (%.2f ms)\n",
298      delta_ticks_internal, delta_ticks.InMillisecondsF());
299
300  const net::URLRequestStatus status = fetcher->GetStatus();
301  if (status.status() != net::URLRequestStatus::SUCCESS) {
302    LOG(ERROR) << "Request failed with error code: "
303               << net::ErrorToString(status.error());
304    return EXIT_FAILURE;
305  }
306
307  const net::HttpResponseHeaders* const headers =
308      fetcher->GetResponseHeaders();
309  if (!headers) {
310    LOG(ERROR) << "Response does not have any headers";
311    return EXIT_FAILURE;
312  }
313
314  void* iter = NULL;
315  std::string date_header;
316  while (headers->EnumerateHeader(&iter, "Date", &date_header)) {
317    std::printf("Got date header: %s\n", date_header.c_str());
318  }
319
320  base::Time server_time;
321  if (!headers->GetDateValue(&server_time)) {
322    LOG(ERROR) << "Could not parse time from server response headers";
323    return EXIT_FAILURE;
324  }
325
326  std::printf(
327      "Got time %s from server\n",
328      UTF16ToUTF8(base::TimeFormatFriendlyDateAndTime(server_time)).c_str());
329
330  base::Time server_now;
331  base::TimeDelta server_now_uncertainty;
332  EstimateServerTimeNow(server_time, start_ticks, end_ticks,
333                        &server_now, &server_now_uncertainty);
334  base::Time now = base::Time::Now();
335
336  std::printf(
337      "According to the server, it is now %s with uncertainty %.2f ms\n",
338      UTF16ToUTF8(base::TimeFormatFriendlyDateAndTime(server_now)).c_str(),
339      server_now_uncertainty.InMillisecondsF());
340
341  base::TimeDelta skew;
342  base::TimeDelta skew_uncertainty;
343  EstimateSkew(server_now, server_now_uncertainty, now,
344               base::TimeDelta::FromMilliseconds(kTimeResolutionMs),
345               &skew, &skew_uncertainty);
346
347  std::printf(
348      "An estimate for the local clock skew is %.2f ms with "
349      "uncertainty %.2f ms\n",
350      skew.InMillisecondsF(),
351      skew_uncertainty.InMillisecondsF());
352
353  return EXIT_SUCCESS;
354}
355