OLD | NEW |
| (Empty) |
1 // Copyright 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 #include "sync/internal_api/public/http_bridge.h" | |
6 | |
7 #include <stddef.h> | |
8 #include <stdint.h> | |
9 | |
10 #include <vector> | |
11 | |
12 #include "base/bit_cast.h" | |
13 #include "base/location.h" | |
14 #include "base/metrics/histogram_macros.h" | |
15 #include "base/metrics/sparse_histogram.h" | |
16 #include "base/single_thread_task_runner.h" | |
17 #include "base/strings/string_number_conversions.h" | |
18 #include "base/strings/stringprintf.h" | |
19 #include "base/threading/thread_task_runner_handle.h" | |
20 #include "net/base/load_flags.h" | |
21 #include "net/base/net_errors.h" | |
22 #include "net/http/http_cache.h" | |
23 #include "net/http/http_network_layer.h" | |
24 #include "net/http/http_request_headers.h" | |
25 #include "net/http/http_response_headers.h" | |
26 #include "net/url_request/static_http_user_agent_settings.h" | |
27 #include "net/url_request/url_fetcher.h" | |
28 #include "net/url_request/url_request_context.h" | |
29 #include "net/url_request/url_request_job_factory_impl.h" | |
30 #include "net/url_request/url_request_status.h" | |
31 #include "sync/internal_api/public/base/cancelation_signal.h" | |
32 | |
33 namespace syncer { | |
34 | |
35 namespace { | |
36 | |
37 // It's possible for an http request to be silently stalled. We set a time | |
38 // limit for all http requests, beyond which the request is cancelled and | |
39 // treated as a transient failure. | |
40 const int kMaxHttpRequestTimeSeconds = 60 * 5; // 5 minutes. | |
41 | |
42 // Helper method for logging timeouts via UMA. | |
43 void LogTimeout(bool timed_out) { | |
44 UMA_HISTOGRAM_BOOLEAN("Sync.URLFetchTimedOut", timed_out); | |
45 } | |
46 | |
47 void RecordSyncRequestContentLengthHistograms(int64_t compressed_content_length, | |
48 int64_t original_content_length) { | |
49 UMA_HISTOGRAM_COUNTS("Sync.RequestContentLength.Compressed", | |
50 compressed_content_length); | |
51 UMA_HISTOGRAM_COUNTS("Sync.RequestContentLength.Original", | |
52 original_content_length); | |
53 } | |
54 | |
55 void RecordSyncResponseContentLengthHistograms( | |
56 int64_t compressed_content_length, | |
57 int64_t original_content_length) { | |
58 UMA_HISTOGRAM_COUNTS("Sync.ResponseContentLength.Compressed", | |
59 compressed_content_length); | |
60 UMA_HISTOGRAM_COUNTS("Sync.ResponseContentLength.Original", | |
61 original_content_length); | |
62 } | |
63 | |
64 } // namespace | |
65 | |
66 HttpBridgeFactory::HttpBridgeFactory( | |
67 const scoped_refptr<net::URLRequestContextGetter>& request_context_getter, | |
68 const NetworkTimeUpdateCallback& network_time_update_callback, | |
69 CancelationSignal* cancelation_signal) | |
70 : request_context_getter_(request_context_getter), | |
71 network_time_update_callback_(network_time_update_callback), | |
72 cancelation_signal_(cancelation_signal) { | |
73 // Registration should never fail. This should happen on the UI thread during | |
74 // init. It would be impossible for a shutdown to have been requested at this | |
75 // point. | |
76 bool result = cancelation_signal_->TryRegisterHandler(this); | |
77 DCHECK(result); | |
78 } | |
79 | |
80 HttpBridgeFactory::~HttpBridgeFactory() { | |
81 cancelation_signal_->UnregisterHandler(this); | |
82 } | |
83 | |
84 void HttpBridgeFactory::Init( | |
85 const std::string& user_agent, | |
86 const BindToTrackerCallback& bind_to_tracker_callback) { | |
87 user_agent_ = user_agent; | |
88 bind_to_tracker_callback_ = bind_to_tracker_callback; | |
89 } | |
90 | |
91 HttpPostProviderInterface* HttpBridgeFactory::Create() { | |
92 base::AutoLock lock(request_context_getter_lock_); | |
93 | |
94 // If we've been asked to shut down (something which may happen asynchronously | |
95 // and at pretty much any time), then we won't have a request_context_getter_. | |
96 // Some external mechanism must ensure that this function is not called after | |
97 // we've been asked to shut down. | |
98 CHECK(request_context_getter_.get()); | |
99 | |
100 scoped_refptr<HttpBridge> http = | |
101 new HttpBridge(user_agent_, request_context_getter_, | |
102 network_time_update_callback_, bind_to_tracker_callback_); | |
103 http->AddRef(); | |
104 return http.get(); | |
105 } | |
106 | |
107 void HttpBridgeFactory::Destroy(HttpPostProviderInterface* http) { | |
108 static_cast<HttpBridge*>(http)->Release(); | |
109 } | |
110 | |
111 void HttpBridgeFactory::OnSignalReceived() { | |
112 base::AutoLock lock(request_context_getter_lock_); | |
113 // Release |request_context_getter_| as soon as possible so that it | |
114 // is destroyed in the right order on its network task runner. | |
115 request_context_getter_ = NULL; | |
116 } | |
117 | |
118 HttpBridge::URLFetchState::URLFetchState() | |
119 : url_poster(NULL), | |
120 aborted(false), | |
121 request_completed(false), | |
122 request_succeeded(false), | |
123 http_response_code(-1), | |
124 error_code(-1) { | |
125 } | |
126 HttpBridge::URLFetchState::~URLFetchState() {} | |
127 | |
128 HttpBridge::HttpBridge( | |
129 const std::string& user_agent, | |
130 const scoped_refptr<net::URLRequestContextGetter>& context_getter, | |
131 const NetworkTimeUpdateCallback& network_time_update_callback, | |
132 const BindToTrackerCallback& bind_to_tracker_callback) | |
133 : user_agent_(user_agent), | |
134 http_post_completed_(base::WaitableEvent::ResetPolicy::AUTOMATIC, | |
135 base::WaitableEvent::InitialState::NOT_SIGNALED), | |
136 request_context_getter_(context_getter), | |
137 network_task_runner_(request_context_getter_->GetNetworkTaskRunner()), | |
138 network_time_update_callback_(network_time_update_callback), | |
139 bind_to_tracker_callback_(bind_to_tracker_callback) {} | |
140 | |
141 HttpBridge::~HttpBridge() { | |
142 } | |
143 | |
144 void HttpBridge::SetExtraRequestHeaders(const char * headers) { | |
145 DCHECK(extra_headers_.empty()) | |
146 << "HttpBridge::SetExtraRequestHeaders called twice."; | |
147 extra_headers_.assign(headers); | |
148 } | |
149 | |
150 void HttpBridge::SetURL(const char* url, int port) { | |
151 #if DCHECK_IS_ON() | |
152 DCHECK(thread_checker_.CalledOnValidThread()); | |
153 { | |
154 base::AutoLock lock(fetch_state_lock_); | |
155 DCHECK(!fetch_state_.request_completed); | |
156 } | |
157 DCHECK(url_for_request_.is_empty()) | |
158 << "HttpBridge::SetURL called more than once?!"; | |
159 #endif | |
160 GURL temp(url); | |
161 GURL::Replacements replacements; | |
162 std::string port_str = base::IntToString(port); | |
163 replacements.SetPort(port_str.c_str(), url::Component(0, port_str.length())); | |
164 url_for_request_ = temp.ReplaceComponents(replacements); | |
165 } | |
166 | |
167 void HttpBridge::SetPostPayload(const char* content_type, | |
168 int content_length, | |
169 const char* content) { | |
170 #if DCHECK_IS_ON() | |
171 DCHECK(thread_checker_.CalledOnValidThread()); | |
172 { | |
173 base::AutoLock lock(fetch_state_lock_); | |
174 DCHECK(!fetch_state_.request_completed); | |
175 } | |
176 DCHECK(content_type_.empty()) << "Bridge payload already set."; | |
177 DCHECK_GE(content_length, 0) << "Content length < 0"; | |
178 #endif | |
179 content_type_ = content_type; | |
180 if (!content || (content_length == 0)) { | |
181 DCHECK_EQ(content_length, 0); | |
182 request_content_ = " "; // TODO(timsteele): URLFetcher requires non-empty | |
183 // content for POSTs whereas CURL does not, for now | |
184 // we hack this to support the sync backend. | |
185 } else { | |
186 request_content_.assign(content, content_length); | |
187 } | |
188 } | |
189 | |
190 bool HttpBridge::MakeSynchronousPost(int* error_code, int* response_code) { | |
191 #if DCHECK_IS_ON() | |
192 DCHECK(thread_checker_.CalledOnValidThread()); | |
193 { | |
194 base::AutoLock lock(fetch_state_lock_); | |
195 DCHECK(!fetch_state_.request_completed); | |
196 } | |
197 DCHECK(url_for_request_.is_valid()) << "Invalid URL for request"; | |
198 DCHECK(!content_type_.empty()) << "Payload not set"; | |
199 #endif | |
200 | |
201 if (!network_task_runner_->PostTask( | |
202 FROM_HERE, | |
203 base::Bind(&HttpBridge::CallMakeAsynchronousPost, this))) { | |
204 // This usually happens when we're in a unit test. | |
205 LOG(WARNING) << "Could not post CallMakeAsynchronousPost task"; | |
206 return false; | |
207 } | |
208 | |
209 // Block until network request completes or is aborted. See | |
210 // OnURLFetchComplete and Abort. | |
211 http_post_completed_.Wait(); | |
212 | |
213 base::AutoLock lock(fetch_state_lock_); | |
214 DCHECK(fetch_state_.request_completed || fetch_state_.aborted); | |
215 *error_code = fetch_state_.error_code; | |
216 *response_code = fetch_state_.http_response_code; | |
217 return fetch_state_.request_succeeded; | |
218 } | |
219 | |
220 void HttpBridge::MakeAsynchronousPost() { | |
221 DCHECK(network_task_runner_->BelongsToCurrentThread()); | |
222 | |
223 base::AutoLock lock(fetch_state_lock_); | |
224 DCHECK(!fetch_state_.request_completed); | |
225 if (fetch_state_.aborted) | |
226 return; | |
227 | |
228 // Start the timer on the network thread (the same thread progress is made | |
229 // on, and on which the url fetcher lives). | |
230 DCHECK(!fetch_state_.http_request_timeout_timer.get()); | |
231 fetch_state_.http_request_timeout_timer.reset(new base::Timer(false, false)); | |
232 fetch_state_.http_request_timeout_timer->Start( | |
233 FROM_HERE, base::TimeDelta::FromSeconds(kMaxHttpRequestTimeSeconds), | |
234 base::Bind(&HttpBridge::OnURLFetchTimedOut, this)); | |
235 | |
236 DCHECK(request_context_getter_.get()); | |
237 fetch_state_.start_time = base::Time::Now(); | |
238 fetch_state_.url_poster = | |
239 net::URLFetcher::Create(url_for_request_, net::URLFetcher::POST, this) | |
240 .release(); | |
241 if (!bind_to_tracker_callback_.is_null()) | |
242 bind_to_tracker_callback_.Run(fetch_state_.url_poster); | |
243 fetch_state_.url_poster->SetRequestContext(request_context_getter_.get()); | |
244 fetch_state_.url_poster->SetExtraRequestHeaders(extra_headers_); | |
245 | |
246 fetch_state_.url_poster->SetUploadData(content_type_, request_content_); | |
247 RecordSyncRequestContentLengthHistograms(request_content_.size(), | |
248 request_content_.size()); | |
249 | |
250 fetch_state_.url_poster->AddExtraRequestHeader(base::StringPrintf( | |
251 "%s: %s", net::HttpRequestHeaders::kUserAgent, user_agent_.c_str())); | |
252 fetch_state_.url_poster->SetLoadFlags(net::LOAD_BYPASS_CACHE | | |
253 net::LOAD_DISABLE_CACHE | | |
254 net::LOAD_DO_NOT_SAVE_COOKIES | | |
255 net::LOAD_DO_NOT_SEND_COOKIES); | |
256 | |
257 fetch_state_.url_poster->Start(); | |
258 } | |
259 | |
260 int HttpBridge::GetResponseContentLength() const { | |
261 DCHECK(thread_checker_.CalledOnValidThread()); | |
262 base::AutoLock lock(fetch_state_lock_); | |
263 DCHECK(fetch_state_.request_completed); | |
264 return fetch_state_.response_content.size(); | |
265 } | |
266 | |
267 const char* HttpBridge::GetResponseContent() const { | |
268 DCHECK(thread_checker_.CalledOnValidThread()); | |
269 base::AutoLock lock(fetch_state_lock_); | |
270 DCHECK(fetch_state_.request_completed); | |
271 return fetch_state_.response_content.data(); | |
272 } | |
273 | |
274 const std::string HttpBridge::GetResponseHeaderValue( | |
275 const std::string& name) const { | |
276 DCHECK(thread_checker_.CalledOnValidThread()); | |
277 base::AutoLock lock(fetch_state_lock_); | |
278 DCHECK(fetch_state_.request_completed); | |
279 | |
280 std::string value; | |
281 fetch_state_.response_headers->EnumerateHeader(NULL, name, &value); | |
282 return value; | |
283 } | |
284 | |
285 void HttpBridge::Abort() { | |
286 base::AutoLock lock(fetch_state_lock_); | |
287 | |
288 // Release |request_context_getter_| as soon as possible so that it is | |
289 // destroyed in the right order on its network task runner. | |
290 request_context_getter_ = NULL; | |
291 | |
292 DCHECK(!fetch_state_.aborted); | |
293 if (fetch_state_.aborted || fetch_state_.request_completed) | |
294 return; | |
295 | |
296 fetch_state_.aborted = true; | |
297 if (!network_task_runner_->PostTask( | |
298 FROM_HERE, | |
299 base::Bind(&HttpBridge::DestroyURLFetcherOnIOThread, this, | |
300 fetch_state_.url_poster, | |
301 fetch_state_.http_request_timeout_timer.release()))) { | |
302 // Madness ensues. | |
303 NOTREACHED() << "Could not post task to delete URLFetcher"; | |
304 } | |
305 | |
306 fetch_state_.url_poster = NULL; | |
307 fetch_state_.error_code = net::ERR_ABORTED; | |
308 http_post_completed_.Signal(); | |
309 } | |
310 | |
311 void HttpBridge::DestroyURLFetcherOnIOThread( | |
312 net::URLFetcher* fetcher, | |
313 base::Timer* fetch_timer) { | |
314 DCHECK(network_task_runner_->BelongsToCurrentThread()); | |
315 if (fetch_timer) | |
316 delete fetch_timer; | |
317 delete fetcher; | |
318 } | |
319 | |
320 void HttpBridge::OnURLFetchComplete(const net::URLFetcher* source) { | |
321 DCHECK(network_task_runner_->BelongsToCurrentThread()); | |
322 | |
323 base::AutoLock lock(fetch_state_lock_); | |
324 | |
325 // Stop the request timer now that the request completed. | |
326 if (fetch_state_.http_request_timeout_timer.get()) | |
327 fetch_state_.http_request_timeout_timer.reset(); | |
328 | |
329 if (fetch_state_.aborted) | |
330 return; | |
331 | |
332 fetch_state_.end_time = base::Time::Now(); | |
333 fetch_state_.request_completed = true; | |
334 fetch_state_.request_succeeded = | |
335 (net::URLRequestStatus::SUCCESS == source->GetStatus().status()); | |
336 fetch_state_.http_response_code = source->GetResponseCode(); | |
337 fetch_state_.error_code = source->GetStatus().error(); | |
338 | |
339 if (fetch_state_.request_succeeded) | |
340 LogTimeout(false); | |
341 UMA_HISTOGRAM_SPARSE_SLOWLY("Sync.URLFetchResponse", | |
342 source->GetStatus().is_success() | |
343 ? source->GetResponseCode() | |
344 : source->GetStatus().ToNetError()); | |
345 UMA_HISTOGRAM_LONG_TIMES("Sync.URLFetchTime", | |
346 fetch_state_.end_time - fetch_state_.start_time); | |
347 | |
348 // Use a real (non-debug) log to facilitate troubleshooting in the wild. | |
349 VLOG(2) << "HttpBridge::OnURLFetchComplete for: " | |
350 << fetch_state_.url_poster->GetURL().spec(); | |
351 VLOG(1) << "HttpBridge received response code: " | |
352 << fetch_state_.http_response_code; | |
353 | |
354 source->GetResponseAsString(&fetch_state_.response_content); | |
355 fetch_state_.response_headers = source->GetResponseHeaders(); | |
356 UpdateNetworkTime(); | |
357 | |
358 int64_t original_content_length = fetch_state_.response_content.size(); | |
359 int64_t compressed_content_length = | |
360 source->GetReceivedResponseContentLength(); | |
361 RecordSyncResponseContentLengthHistograms(compressed_content_length, | |
362 original_content_length); | |
363 | |
364 // End of the line for url_poster_. It lives only on the IO loop. | |
365 // We defer deletion because we're inside a callback from a component of the | |
366 // URLFetcher, so it seems most natural / "polite" to let the stack unwind. | |
367 base::ThreadTaskRunnerHandle::Get()->DeleteSoon(FROM_HERE, | |
368 fetch_state_.url_poster); | |
369 fetch_state_.url_poster = NULL; | |
370 | |
371 // Wake the blocked syncer thread in MakeSynchronousPost. | |
372 // WARNING: DONT DO ANYTHING AFTER THIS CALL! |this| may be deleted! | |
373 http_post_completed_.Signal(); | |
374 } | |
375 | |
376 void HttpBridge::OnURLFetchDownloadProgress(const net::URLFetcher* source, | |
377 int64_t current, | |
378 int64_t total) { | |
379 DCHECK(network_task_runner_->BelongsToCurrentThread()); | |
380 // Reset the delay when forward progress is made. | |
381 base::AutoLock lock(fetch_state_lock_); | |
382 if (fetch_state_.http_request_timeout_timer.get()) | |
383 fetch_state_.http_request_timeout_timer->Reset(); | |
384 } | |
385 | |
386 void HttpBridge::OnURLFetchUploadProgress(const net::URLFetcher* source, | |
387 int64_t current, | |
388 int64_t total) { | |
389 DCHECK(network_task_runner_->BelongsToCurrentThread()); | |
390 // Reset the delay when forward progress is made. | |
391 base::AutoLock lock(fetch_state_lock_); | |
392 if (fetch_state_.http_request_timeout_timer.get()) | |
393 fetch_state_.http_request_timeout_timer->Reset(); | |
394 } | |
395 | |
396 void HttpBridge::OnURLFetchTimedOut() { | |
397 DCHECK(network_task_runner_->BelongsToCurrentThread()); | |
398 | |
399 base::AutoLock lock(fetch_state_lock_); | |
400 if (!fetch_state_.url_poster) | |
401 return; | |
402 | |
403 LogTimeout(true); | |
404 DVLOG(1) << "Sync url fetch timed out. Canceling."; | |
405 | |
406 fetch_state_.end_time = base::Time::Now(); | |
407 fetch_state_.request_completed = true; | |
408 fetch_state_.request_succeeded = false; | |
409 fetch_state_.http_response_code = -1; | |
410 fetch_state_.error_code = net::ERR_TIMED_OUT; | |
411 | |
412 // This method is called by the timer, not the url fetcher implementation, | |
413 // so it's safe to delete the fetcher here. | |
414 delete fetch_state_.url_poster; | |
415 fetch_state_.url_poster = NULL; | |
416 | |
417 // Timer is smart enough to handle being deleted as part of the invoked task. | |
418 fetch_state_.http_request_timeout_timer.reset(); | |
419 | |
420 // Wake the blocked syncer thread in MakeSynchronousPost. | |
421 // WARNING: DONT DO ANYTHING AFTER THIS CALL! |this| may be deleted! | |
422 http_post_completed_.Signal(); | |
423 } | |
424 | |
425 net::URLRequestContextGetter* HttpBridge::GetRequestContextGetterForTest() | |
426 const { | |
427 base::AutoLock lock(fetch_state_lock_); | |
428 return request_context_getter_.get(); | |
429 } | |
430 | |
431 void HttpBridge::UpdateNetworkTime() { | |
432 std::string sane_time_str; | |
433 if (!fetch_state_.request_succeeded || fetch_state_.start_time.is_null() || | |
434 fetch_state_.end_time < fetch_state_.start_time || | |
435 !fetch_state_.response_headers || | |
436 !fetch_state_.response_headers->EnumerateHeader(NULL, "Sane-Time-Millis", | |
437 &sane_time_str)) { | |
438 return; | |
439 } | |
440 | |
441 int64_t sane_time_ms = 0; | |
442 if (base::StringToInt64(sane_time_str, &sane_time_ms)) { | |
443 network_time_update_callback_.Run( | |
444 base::Time::FromJsTime(sane_time_ms), | |
445 base::TimeDelta::FromMilliseconds(1), | |
446 fetch_state_.end_time - fetch_state_.start_time); | |
447 } | |
448 } | |
449 | |
450 } // namespace syncer | |
OLD | NEW |