1 // Copyright 2014 The Chromium Authors
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 "net/log/net_log_util.h"
6
7 #include <algorithm>
8 #include <string>
9 #include <utility>
10 #include <vector>
11
12 #include "base/check_op.h"
13 #include "base/feature_list.h"
14 #include "base/metrics/field_trial.h"
15 #include "base/strings/strcat.h"
16 #include "base/strings/string_number_conversions.h"
17 #include "base/strings/string_split.h"
18 #include "base/strings/string_util.h"
19 #include "base/time/time.h"
20 #include "base/values.h"
21 #include "net/base/address_family.h"
22 #include "net/base/load_states.h"
23 #include "net/base/net_errors.h"
24 #include "net/base/net_info_source_list.h"
25 #include "net/cert/cert_verifier.h"
26 #include "net/cert/pki/simple_path_builder_delegate.h"
27 #include "net/cert/pki/trust_store.h"
28 #include "net/disk_cache/disk_cache.h"
29 #include "net/dns/host_cache.h"
30 #include "net/dns/host_resolver.h"
31 #include "net/dns/public/dns_query_type.h"
32 #include "net/dns/public/doh_provider_entry.h"
33 #include "net/dns/public/secure_dns_mode.h"
34 #include "net/http/http_cache.h"
35 #include "net/http/http_network_session.h"
36 #include "net/http/http_server_properties.h"
37 #include "net/http/http_transaction_factory.h"
38 #include "net/log/net_log_capture_mode.h"
39 #include "net/log/net_log_entry.h"
40 #include "net/log/net_log_event_type.h"
41 #include "net/log/net_log_values.h"
42 #include "net/log/net_log_with_source.h"
43 #include "net/proxy_resolution/proxy_config.h"
44 #include "net/proxy_resolution/proxy_resolution_service.h"
45 #include "net/proxy_resolution/proxy_retry_info.h"
46 #include "net/socket/ssl_client_socket.h"
47 #include "net/third_party/quiche/src/quiche/quic/core/quic_error_codes.h"
48 #include "net/third_party/quiche/src/quiche/quic/core/quic_packets.h"
49 #include "net/url_request/url_request.h"
50 #include "net/url_request/url_request_context.h"
51
52 #if BUILDFLAG(ENABLE_REPORTING)
53 #include "net/network_error_logging/network_error_logging_service.h"
54 #include "net/reporting/reporting_service.h"
55 #endif // BUILDFLAG(ENABLE_REPORTING)
56
57 namespace net {
58
59 namespace {
60
61 // This should be incremented when significant changes are made that will
62 // invalidate the old loading code.
63 const int kLogFormatVersion = 1;
64
65 struct StringToConstant {
66 const char* name;
67 const int constant;
68 };
69
70 const StringToConstant kCertStatusFlags[] = {
71 #define CERT_STATUS_FLAG(label, value) {#label, value},
72 #include "net/cert/cert_status_flags_list.h"
73 #undef CERT_STATUS_FLAG
74 };
75
76 const StringToConstant kLoadFlags[] = {
77 #define LOAD_FLAG(label, value) {#label, value},
78 #include "net/base/load_flags_list.h"
79 #undef LOAD_FLAG
80 };
81
82 const StringToConstant kLoadStateTable[] = {
83 #define LOAD_STATE(label, value) {#label, LOAD_STATE_##label},
84 #include "net/base/load_states_list.h"
85 #undef LOAD_STATE
86 };
87
88 const short kNetErrors[] = {
89 #define NET_ERROR(label, value) value,
90 #include "net/base/net_error_list.h"
91 #undef NET_ERROR
92 };
93
94 // Returns the disk cache backend for |context| if there is one, or NULL.
95 // Despite the name, can return an in memory "disk cache".
GetDiskCacheBackend(URLRequestContext * context)96 disk_cache::Backend* GetDiskCacheBackend(URLRequestContext* context) {
97 if (!context->http_transaction_factory())
98 return nullptr;
99
100 HttpCache* http_cache = context->http_transaction_factory()->GetCache();
101 if (!http_cache)
102 return nullptr;
103
104 return http_cache->GetCurrentBackend();
105 }
106
107 // Returns true if |request1| was created before |request2|.
RequestCreatedBefore(const URLRequest * request1,const URLRequest * request2)108 bool RequestCreatedBefore(const URLRequest* request1,
109 const URLRequest* request2) {
110 // Only supported when both requests have the same non-null NetLog.
111 DCHECK(request1->net_log().net_log());
112 DCHECK_EQ(request1->net_log().net_log(), request2->net_log().net_log());
113
114 if (request1->creation_time() < request2->creation_time())
115 return true;
116 if (request1->creation_time() > request2->creation_time())
117 return false;
118 // If requests were created at the same time, sort by NetLogSource ID. Some
119 // NetLog tests assume the returned order exactly matches creation order, even
120 // creation times of two events are potentially the same.
121 return request1->net_log().source().id < request2->net_log().source().id;
122 }
123
GetActiveFieldTrialList()124 base::Value GetActiveFieldTrialList() {
125 base::FieldTrial::ActiveGroups active_groups;
126 base::FieldTrialList::GetActiveFieldTrialGroups(&active_groups);
127 base::Value::List field_trial_groups;
128 for (const auto& group : active_groups) {
129 field_trial_groups.Append(group.trial_name + ":" + group.group_name);
130 }
131 return base::Value(std::move(field_trial_groups));
132 }
133
134 } // namespace
135
GetNetConstants()136 base::Value::Dict GetNetConstants() {
137 base::Value::Dict constants_dict;
138
139 // Version of the file format.
140 constants_dict.Set("logFormatVersion", kLogFormatVersion);
141
142 // Add a dictionary with information on the relationship between event type
143 // enums and their symbolic names.
144 constants_dict.Set("logEventTypes", NetLog::GetEventTypesAsValue());
145
146 // Add a dictionary with information about the relationship between CertStatus
147 // flags and their symbolic names.
148 {
149 base::Value::Dict dict;
150
151 for (const auto& flag : kCertStatusFlags)
152 dict.Set(flag.name, flag.constant);
153
154 constants_dict.Set("certStatusFlag", std::move(dict));
155 }
156
157 // Add a dictionary with information about the relationship between
158 // CertVerifier::VerifyFlags and their symbolic names.
159 {
160 static_assert(CertVerifier::VERIFY_FLAGS_LAST == (1 << 0),
161 "Update with new flags");
162 constants_dict.Set(
163 "certVerifierFlags",
164 base::Value::Dict().Set("VERIFY_DISABLE_NETWORK_FETCHES",
165 CertVerifier::VERIFY_DISABLE_NETWORK_FETCHES));
166 }
167
168 {
169 static_assert(SimplePathBuilderDelegate::DigestPolicy::kMaxValue ==
170 SimplePathBuilderDelegate::DigestPolicy::kWeakAllowSha1,
171 "Update with new flags");
172
173 constants_dict.Set(
174 "certPathBuilderDigestPolicy",
175 base::Value::Dict()
176 .Set("kStrong",
177 static_cast<int>(
178 SimplePathBuilderDelegate::DigestPolicy::kStrong))
179 .Set("kWeakAllowSha1",
180 static_cast<int>(
181 SimplePathBuilderDelegate::DigestPolicy::kWeakAllowSha1)));
182 }
183
184 // Add a dictionary with information about the relationship between load flag
185 // enums and their symbolic names.
186 {
187 base::Value::Dict dict;
188
189 for (const auto& flag : kLoadFlags)
190 dict.Set(flag.name, flag.constant);
191
192 constants_dict.Set("loadFlag", std::move(dict));
193 }
194
195 // Add a dictionary with information about the relationship between load state
196 // enums and their symbolic names.
197 {
198 base::Value::Dict dict;
199
200 for (const auto& state : kLoadStateTable)
201 dict.Set(state.name, state.constant);
202
203 constants_dict.Set("loadState", std::move(dict));
204 }
205
206 // Add information on the relationship between net error codes and their
207 // symbolic names.
208 {
209 base::Value::Dict dict;
210
211 for (const auto& error : kNetErrors)
212 dict.Set(ErrorToShortString(error), error);
213
214 constants_dict.Set("netError", std::move(dict));
215 }
216
217 // Add information on the relationship between QUIC error codes and their
218 // symbolic names.
219 {
220 base::Value::Dict dict;
221
222 for (quic::QuicErrorCode error = quic::QUIC_NO_ERROR;
223 error < quic::QUIC_LAST_ERROR;
224 error = static_cast<quic::QuicErrorCode>(error + 1)) {
225 dict.Set(QuicErrorCodeToString(error), static_cast<int>(error));
226 }
227
228 constants_dict.Set("quicError", std::move(dict));
229 }
230
231 // Add information on the relationship between QUIC RST_STREAM error codes
232 // and their symbolic names.
233 {
234 base::Value::Dict dict;
235
236 for (quic::QuicRstStreamErrorCode error = quic::QUIC_STREAM_NO_ERROR;
237 error < quic::QUIC_STREAM_LAST_ERROR;
238 error = static_cast<quic::QuicRstStreamErrorCode>(error + 1)) {
239 dict.Set(QuicRstStreamErrorCodeToString(error), static_cast<int>(error));
240 }
241
242 constants_dict.Set("quicRstStreamError", std::move(dict));
243 }
244
245 // Information about the relationship between event phase enums and their
246 // symbolic names.
247 {
248 constants_dict.Set(
249 "logEventPhase",
250 base::Value::Dict()
251 .Set("PHASE_BEGIN", static_cast<int>(NetLogEventPhase::BEGIN))
252 .Set("PHASE_END", static_cast<int>(NetLogEventPhase::END))
253 .Set("PHASE_NONE", static_cast<int>(NetLogEventPhase::NONE)));
254 }
255
256 // Information about the relationship between source type enums and
257 // their symbolic names.
258 constants_dict.Set("logSourceType", NetLog::GetSourceTypesAsValue());
259
260 // Information about the relationship between address family enums and
261 // their symbolic names.
262 {
263 constants_dict.Set(
264 "addressFamily",
265 base::Value::Dict()
266 .Set("ADDRESS_FAMILY_UNSPECIFIED", ADDRESS_FAMILY_UNSPECIFIED)
267 .Set("ADDRESS_FAMILY_IPV4", ADDRESS_FAMILY_IPV4)
268 .Set("ADDRESS_FAMILY_IPV6", ADDRESS_FAMILY_IPV6));
269 }
270
271 // Information about the relationship between DnsQueryType enums and their
272 // symbolic names.
273 {
274 base::Value::Dict dict;
275 for (const auto& type : kDnsQueryTypes) {
276 dict.Set(type.second, static_cast<int>(type.first));
277 }
278 constants_dict.Set("dnsQueryType", std::move(dict));
279 }
280
281 // Information about the relationship between SecureDnsMode enums and their
282 // symbolic names.
283 {
284 base::Value::Dict dict;
285 for (const auto& mode : kSecureDnsModes) {
286 dict.Set(mode.second, static_cast<int>(mode.first));
287 }
288 constants_dict.Set("secureDnsMode", std::move(dict));
289 }
290
291 // Information about how the "time ticks" values we have given it relate to
292 // actual system times. Time ticks are used throughout since they are stable
293 // across system clock changes. Note: |timeTickOffset| is only comparable to
294 // TimeTicks values in milliseconds.
295 // TODO(csharrison): This is an imprecise way to convert TimeTicks to unix
296 // time. In fact, there isn't really a good way to do this unless we log Time
297 // and TimeTicks values side by side for every event. crbug.com/593157 tracks
298 // a change where the user will be notified if a timing anomaly occured that
299 // would skew the conversion (i.e. the machine entered suspend mode while
300 // logging).
301 {
302 base::TimeDelta time_since_epoch =
303 base::Time::Now() - base::Time::UnixEpoch();
304 base::TimeDelta reference_time_ticks =
305 base::TimeTicks::Now() - base::TimeTicks();
306 int64_t tick_to_unix_time_ms =
307 (time_since_epoch - reference_time_ticks).InMilliseconds();
308 constants_dict.Set("timeTickOffset",
309 NetLogNumberValue(tick_to_unix_time_ms));
310 }
311
312 // TODO(eroman): Is this needed?
313 // "clientInfo" key is required for some log readers. Provide a default empty
314 // value for compatibility.
315 constants_dict.Set("clientInfo", base::Value::Dict());
316
317 // Add a list of field experiments active at the start of the capture.
318 // Additional trials may be enabled later in the browser session.
319 constants_dict.Set(kNetInfoFieldTrials, GetActiveFieldTrialList());
320
321 return constants_dict;
322 }
323
GetNetInfo(URLRequestContext * context)324 NET_EXPORT base::Value::Dict GetNetInfo(URLRequestContext* context) {
325 // May only be called on the context's thread.
326 context->AssertCalledOnValidThread();
327
328 base::Value::Dict net_info_dict =
329 context->proxy_resolution_service()->GetProxyNetLogValues();
330
331 // Log Host Resolver info.
332 {
333 HostResolver* host_resolver = context->host_resolver();
334 DCHECK(host_resolver);
335 HostCache* cache = host_resolver->GetHostCache();
336 if (cache) {
337 base::Value::List cache_contents_list;
338 cache->GetList(cache_contents_list, true /* include_staleness */,
339 HostCache::SerializationType::kDebug);
340
341 net_info_dict.Set(
342 kNetInfoHostResolver,
343 base::Value::Dict()
344 .Set("dns_config", host_resolver->GetDnsConfigAsValue())
345 .Set("cache",
346 base::Value::Dict()
347 .Set("capacity", static_cast<int>(cache->max_entries()))
348 .Set("network_changes", cache->network_changes())
349 .Set("entries", std::move(cache_contents_list))));
350 }
351
352 // Construct a list containing the names of the disabled DoH providers.
353 base::Value::List disabled_doh_providers_list;
354 for (const DohProviderEntry* provider : DohProviderEntry::GetList()) {
355 if (!base::FeatureList::IsEnabled(provider->feature)) {
356 disabled_doh_providers_list.Append(
357 NetLogStringValue(provider->provider));
358 }
359 }
360 net_info_dict.Set(kNetInfoDohProvidersDisabledDueToFeature,
361 base::Value(std::move(disabled_doh_providers_list)));
362 }
363
364 HttpNetworkSession* http_network_session =
365 context->http_transaction_factory()->GetSession();
366
367 // Log Socket Pool info.
368 {
369 net_info_dict.Set(kNetInfoSocketPool,
370 http_network_session->SocketPoolInfoToValue());
371 }
372
373 // Log SPDY Sessions.
374 {
375 net_info_dict.Set(kNetInfoSpdySessions,
376 base::Value::FromUniquePtrValue(
377 http_network_session->SpdySessionPoolInfoToValue()));
378 }
379
380 // Log SPDY status.
381 {
382 base::Value::Dict status_dict;
383
384 status_dict.Set("enable_http2",
385 http_network_session->params().enable_http2);
386
387 const NextProtoVector& alpn_protos = http_network_session->GetAlpnProtos();
388 if (!alpn_protos.empty()) {
389 std::string next_protos_string;
390 for (NextProto proto : alpn_protos) {
391 if (!next_protos_string.empty())
392 next_protos_string.append(",");
393 next_protos_string.append(NextProtoToString(proto));
394 }
395 status_dict.Set("alpn_protos", next_protos_string);
396 }
397
398 const SSLConfig::ApplicationSettings& application_settings =
399 http_network_session->GetApplicationSettings();
400 if (!application_settings.empty()) {
401 base::Value::Dict application_settings_dict;
402 for (const auto& setting : application_settings) {
403 application_settings_dict.Set(
404 NextProtoToString(setting.first),
405 base::HexEncode(setting.second.data(), setting.second.size()));
406 }
407 status_dict.Set("application_settings",
408 std::move(application_settings_dict));
409 }
410
411 net_info_dict.Set(kNetInfoSpdyStatus, std::move(status_dict));
412 }
413
414 // Log ALT_SVC mappings.
415 {
416 const HttpServerProperties& http_server_properties =
417 *context->http_server_properties();
418 net_info_dict.Set(
419 kNetInfoAltSvcMappings,
420 http_server_properties.GetAlternativeServiceInfoAsValue());
421 }
422
423 // Log QUIC info.
424 { net_info_dict.Set(kNetInfoQuic, http_network_session->QuicInfoToValue()); }
425
426 // Log HTTP Cache info.
427 {
428 base::Value::Dict info_dict;
429 base::Value::Dict stats_dict;
430
431 disk_cache::Backend* disk_cache = GetDiskCacheBackend(context);
432
433 if (disk_cache) {
434 // Extract the statistics key/value pairs from the backend.
435 base::StringPairs stats;
436 disk_cache->GetStats(&stats);
437 for (auto& stat : stats) {
438 stats_dict.Set(stat.first, std::move(stat.second));
439 }
440 }
441 info_dict.Set("stats", std::move(stats_dict));
442
443 net_info_dict.Set(kNetInfoHTTPCache, std::move(info_dict));
444 }
445
446 // Log Reporting API info.
447 {
448 #if BUILDFLAG(ENABLE_REPORTING)
449 ReportingService* reporting_service = context->reporting_service();
450 if (reporting_service) {
451 base::Value reporting_value = reporting_service->StatusAsValue();
452 NetworkErrorLoggingService* network_error_logging_service =
453 context->network_error_logging_service();
454 if (network_error_logging_service) {
455 reporting_value.GetDict().Set(
456 "networkErrorLogging",
457 network_error_logging_service->StatusAsValue());
458 }
459 net_info_dict.Set(kNetInfoReporting, std::move(reporting_value));
460 } else {
461 net_info_dict.Set(kNetInfoReporting,
462 base::Value::Dict().Set("reportingEnabled", false));
463 }
464
465 #else // BUILDFLAG(ENABLE_REPORTING)
466 net_info_dict.Set(kNetInfoReporting,
467 base::Value::Dict().Set("reportingEnabled", false));
468 #endif // BUILDFLAG(ENABLE_REPORTING)
469 }
470
471 // Log currently-active field trials. New trials may have been enabled since
472 // the start of this browser session (crbug.com/1133396).
473 net_info_dict.Set(kNetInfoFieldTrials, GetActiveFieldTrialList());
474
475 return net_info_dict;
476 }
477
CreateNetLogEntriesForActiveObjects(const std::set<URLRequestContext * > & contexts,NetLog::ThreadSafeObserver * observer)478 NET_EXPORT void CreateNetLogEntriesForActiveObjects(
479 const std::set<URLRequestContext*>& contexts,
480 NetLog::ThreadSafeObserver* observer) {
481 // Put together the list of all requests.
482 std::vector<const URLRequest*> requests;
483 for (auto* context : contexts) {
484 // May only be called on the context's thread.
485 context->AssertCalledOnValidThread();
486 // Contexts should all be using the same NetLog.
487 DCHECK_EQ((*contexts.begin())->net_log(), context->net_log());
488 for (auto* request : *context->url_requests()) {
489 requests.push_back(request);
490 }
491 }
492
493 // Sort by creation time.
494 std::sort(requests.begin(), requests.end(), RequestCreatedBefore);
495
496 // Create fake events.
497 for (auto* request : requests) {
498 NetLogEntry entry(NetLogEventType::REQUEST_ALIVE,
499 request->net_log().source(), NetLogEventPhase::BEGIN,
500 request->creation_time(), request->GetStateAsValue());
501 observer->OnAddEntry(entry);
502 }
503 }
504
505 } // namespace net
506