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/disk_cache/disk_cache.h"
27 #include "net/dns/host_cache.h"
28 #include "net/dns/host_resolver.h"
29 #include "net/dns/public/dns_query_type.h"
30 #include "net/dns/public/doh_provider_entry.h"
31 #include "net/dns/public/secure_dns_mode.h"
32 #include "net/http/http_cache.h"
33 #include "net/http/http_network_session.h"
34 #include "net/http/http_server_properties.h"
35 #include "net/http/http_transaction_factory.h"
36 #include "net/log/net_log_capture_mode.h"
37 #include "net/log/net_log_entry.h"
38 #include "net/log/net_log_event_type.h"
39 #include "net/log/net_log_values.h"
40 #include "net/log/net_log_with_source.h"
41 #include "net/proxy_resolution/proxy_config.h"
42 #include "net/proxy_resolution/proxy_resolution_service.h"
43 #include "net/proxy_resolution/proxy_retry_info.h"
44 #include "net/socket/ssl_client_socket.h"
45 #include "net/third_party/quiche/src/quiche/quic/core/quic_error_codes.h"
46 #include "net/third_party/quiche/src/quiche/quic/core/quic_packets.h"
47 #include "net/url_request/url_request.h"
48 #include "net/url_request/url_request_context.h"
49 #include "third_party/boringssl/src/pki/simple_path_builder_delegate.h"
50 #include "third_party/boringssl/src/pki/trust_store.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(CertVerifyProc::VERIFY_FLAGS_LAST == (1 << 4),
170 "Update with new flags");
171 constants_dict.Set(
172 "certVerifyFlags",
173 base::Value::Dict()
174 .Set("VERIFY_REV_CHECKING_ENABLED",
175 CertVerifyProc::VERIFY_REV_CHECKING_ENABLED)
176 .Set("VERIFY_REV_CHECKING_REQUIRED_LOCAL_ANCHORS",
177 CertVerifyProc::VERIFY_REV_CHECKING_REQUIRED_LOCAL_ANCHORS)
178 .Set("VERIFY_ENABLE_SHA1_LOCAL_ANCHORS",
179 CertVerifyProc::VERIFY_ENABLE_SHA1_LOCAL_ANCHORS)
180 .Set("VERIFY_DISABLE_SYMANTEC_ENFORCEMENT",
181 CertVerifyProc::VERIFY_DISABLE_SYMANTEC_ENFORCEMENT)
182 .Set("VERIFY_DISABLE_NETWORK_FETCHES",
183 CertVerifyProc::VERIFY_DISABLE_NETWORK_FETCHES));
184 }
185
186 {
187 static_assert(
188 bssl::SimplePathBuilderDelegate::DigestPolicy::kMaxValue ==
189 bssl::SimplePathBuilderDelegate::DigestPolicy::kWeakAllowSha1,
190 "Update with new flags");
191
192 constants_dict.Set(
193 "certPathBuilderDigestPolicy",
194 base::Value::Dict()
195 .Set("kStrong",
196 static_cast<int>(
197 bssl::SimplePathBuilderDelegate::DigestPolicy::kStrong))
198 .Set("kWeakAllowSha1",
199 static_cast<int>(bssl::SimplePathBuilderDelegate::
200 DigestPolicy::kWeakAllowSha1)));
201 }
202
203 // Add a dictionary with information about the relationship between load flag
204 // enums and their symbolic names.
205 {
206 base::Value::Dict dict;
207
208 for (const auto& flag : kLoadFlags)
209 dict.Set(flag.name, flag.constant);
210
211 constants_dict.Set("loadFlag", std::move(dict));
212 }
213
214 // Add a dictionary with information about the relationship between load state
215 // enums and their symbolic names.
216 {
217 base::Value::Dict dict;
218
219 for (const auto& state : kLoadStateTable)
220 dict.Set(state.name, state.constant);
221
222 constants_dict.Set("loadState", std::move(dict));
223 }
224
225 // Add information on the relationship between net error codes and their
226 // symbolic names.
227 {
228 base::Value::Dict dict;
229
230 for (const auto& error : kNetErrors)
231 dict.Set(ErrorToShortString(error), error);
232
233 constants_dict.Set("netError", std::move(dict));
234 }
235
236 // Add information on the relationship between QUIC error codes and their
237 // symbolic names.
238 {
239 base::Value::Dict dict;
240
241 for (quic::QuicErrorCode error = quic::QUIC_NO_ERROR;
242 error < quic::QUIC_LAST_ERROR;
243 error = static_cast<quic::QuicErrorCode>(error + 1)) {
244 dict.Set(QuicErrorCodeToString(error), static_cast<int>(error));
245 }
246
247 constants_dict.Set("quicError", std::move(dict));
248 }
249
250 // Add information on the relationship between QUIC RST_STREAM error codes
251 // and their symbolic names.
252 {
253 base::Value::Dict dict;
254
255 for (quic::QuicRstStreamErrorCode error = quic::QUIC_STREAM_NO_ERROR;
256 error < quic::QUIC_STREAM_LAST_ERROR;
257 error = static_cast<quic::QuicRstStreamErrorCode>(error + 1)) {
258 dict.Set(QuicRstStreamErrorCodeToString(error), static_cast<int>(error));
259 }
260
261 constants_dict.Set("quicRstStreamError", std::move(dict));
262 }
263
264 // Information about the relationship between event phase enums and their
265 // symbolic names.
266 {
267 constants_dict.Set(
268 "logEventPhase",
269 base::Value::Dict()
270 .Set("PHASE_BEGIN", static_cast<int>(NetLogEventPhase::BEGIN))
271 .Set("PHASE_END", static_cast<int>(NetLogEventPhase::END))
272 .Set("PHASE_NONE", static_cast<int>(NetLogEventPhase::NONE)));
273 }
274
275 // Information about the relationship between source type enums and
276 // their symbolic names.
277 constants_dict.Set("logSourceType", NetLog::GetSourceTypesAsValue());
278
279 // Information about the relationship between address family enums and
280 // their symbolic names.
281 {
282 constants_dict.Set(
283 "addressFamily",
284 base::Value::Dict()
285 .Set("ADDRESS_FAMILY_UNSPECIFIED", ADDRESS_FAMILY_UNSPECIFIED)
286 .Set("ADDRESS_FAMILY_IPV4", ADDRESS_FAMILY_IPV4)
287 .Set("ADDRESS_FAMILY_IPV6", ADDRESS_FAMILY_IPV6));
288 }
289
290 // Information about the relationship between DnsQueryType enums and their
291 // symbolic names.
292 {
293 base::Value::Dict dict;
294 for (const auto& type : kDnsQueryTypes) {
295 dict.Set(type.second, static_cast<int>(type.first));
296 }
297 constants_dict.Set("dnsQueryType", std::move(dict));
298 }
299
300 // Information about the relationship between SecureDnsMode enums and their
301 // symbolic names.
302 {
303 base::Value::Dict dict;
304 for (const auto& mode : kSecureDnsModes) {
305 dict.Set(mode.second, static_cast<int>(mode.first));
306 }
307 constants_dict.Set("secureDnsMode", std::move(dict));
308 }
309
310 // Information about how the "time ticks" values we have given it relate to
311 // actual system times. Time ticks are used throughout since they are stable
312 // across system clock changes. Note: |timeTickOffset| is only comparable to
313 // TimeTicks values in milliseconds.
314 // TODO(csharrison): This is an imprecise way to convert TimeTicks to unix
315 // time. In fact, there isn't really a good way to do this unless we log Time
316 // and TimeTicks values side by side for every event. crbug.com/593157 tracks
317 // a change where the user will be notified if a timing anomaly occured that
318 // would skew the conversion (i.e. the machine entered suspend mode while
319 // logging).
320 {
321 base::TimeDelta time_since_epoch =
322 base::Time::Now() - base::Time::UnixEpoch();
323 base::TimeDelta reference_time_ticks =
324 base::TimeTicks::Now() - base::TimeTicks();
325 int64_t tick_to_unix_time_ms =
326 (time_since_epoch - reference_time_ticks).InMilliseconds();
327 constants_dict.Set("timeTickOffset",
328 NetLogNumberValue(tick_to_unix_time_ms));
329 }
330
331 // TODO(eroman): Is this needed?
332 // "clientInfo" key is required for some log readers. Provide a default empty
333 // value for compatibility.
334 constants_dict.Set("clientInfo", base::Value::Dict());
335
336 // Add a list of field experiments active at the start of the capture.
337 // Additional trials may be enabled later in the browser session.
338 constants_dict.Set(kNetInfoFieldTrials, GetActiveFieldTrialList());
339
340 return constants_dict;
341 }
342
GetNetInfo(URLRequestContext * context)343 NET_EXPORT base::Value::Dict GetNetInfo(URLRequestContext* context) {
344 // May only be called on the context's thread.
345 context->AssertCalledOnValidThread();
346
347 base::Value::Dict net_info_dict =
348 context->proxy_resolution_service()->GetProxyNetLogValues();
349
350 // Log Host Resolver info.
351 {
352 HostResolver* host_resolver = context->host_resolver();
353 DCHECK(host_resolver);
354 HostCache* cache = host_resolver->GetHostCache();
355 if (cache) {
356 base::Value::List cache_contents_list;
357 cache->GetList(cache_contents_list, true /* include_staleness */,
358 HostCache::SerializationType::kDebug);
359
360 net_info_dict.Set(
361 kNetInfoHostResolver,
362 base::Value::Dict()
363 .Set("dns_config", host_resolver->GetDnsConfigAsValue())
364 .Set("cache",
365 base::Value::Dict()
366 .Set("capacity", static_cast<int>(cache->max_entries()))
367 .Set("network_changes", cache->network_changes())
368 .Set("entries", std::move(cache_contents_list))));
369 }
370
371 // Construct a list containing the names of the disabled DoH providers.
372 base::Value::List disabled_doh_providers_list;
373 for (const DohProviderEntry* provider : DohProviderEntry::GetList()) {
374 if (!base::FeatureList::IsEnabled(provider->feature)) {
375 disabled_doh_providers_list.Append(
376 NetLogStringValue(provider->provider));
377 }
378 }
379 net_info_dict.Set(kNetInfoDohProvidersDisabledDueToFeature,
380 base::Value(std::move(disabled_doh_providers_list)));
381 }
382
383 HttpNetworkSession* http_network_session =
384 context->http_transaction_factory()->GetSession();
385
386 // Log Socket Pool info.
387 {
388 net_info_dict.Set(kNetInfoSocketPool,
389 http_network_session->SocketPoolInfoToValue());
390 }
391
392 // Log SPDY Sessions.
393 {
394 net_info_dict.Set(kNetInfoSpdySessions,
395 base::Value::FromUniquePtrValue(
396 http_network_session->SpdySessionPoolInfoToValue()));
397 }
398
399 // Log SPDY status.
400 {
401 base::Value::Dict status_dict;
402
403 status_dict.Set("enable_http2",
404 http_network_session->params().enable_http2);
405
406 const NextProtoVector& alpn_protos = http_network_session->GetAlpnProtos();
407 if (!alpn_protos.empty()) {
408 std::string next_protos_string;
409 for (NextProto proto : alpn_protos) {
410 if (!next_protos_string.empty())
411 next_protos_string.append(",");
412 next_protos_string.append(NextProtoToString(proto));
413 }
414 status_dict.Set("alpn_protos", next_protos_string);
415 }
416
417 const SSLConfig::ApplicationSettings& application_settings =
418 http_network_session->GetApplicationSettings();
419 if (!application_settings.empty()) {
420 base::Value::Dict application_settings_dict;
421 for (const auto& setting : application_settings) {
422 application_settings_dict.Set(NextProtoToString(setting.first),
423 base::HexEncode(setting.second));
424 }
425 status_dict.Set("application_settings",
426 std::move(application_settings_dict));
427 }
428
429 net_info_dict.Set(kNetInfoSpdyStatus, std::move(status_dict));
430 }
431
432 // Log ALT_SVC mappings.
433 {
434 const HttpServerProperties& http_server_properties =
435 *context->http_server_properties();
436 net_info_dict.Set(
437 kNetInfoAltSvcMappings,
438 http_server_properties.GetAlternativeServiceInfoAsValue());
439 }
440
441 // Log QUIC info.
442 { net_info_dict.Set(kNetInfoQuic, http_network_session->QuicInfoToValue()); }
443
444 // Log HTTP Cache info.
445 {
446 base::Value::Dict info_dict;
447 base::Value::Dict stats_dict;
448
449 disk_cache::Backend* disk_cache = GetDiskCacheBackend(context);
450
451 if (disk_cache) {
452 // Extract the statistics key/value pairs from the backend.
453 base::StringPairs stats;
454 disk_cache->GetStats(&stats);
455 for (auto& stat : stats) {
456 stats_dict.Set(stat.first, std::move(stat.second));
457 }
458 }
459 info_dict.Set("stats", std::move(stats_dict));
460
461 net_info_dict.Set(kNetInfoHTTPCache, std::move(info_dict));
462 }
463
464 // Log Reporting API info.
465 {
466 #if BUILDFLAG(ENABLE_REPORTING)
467 ReportingService* reporting_service = context->reporting_service();
468 if (reporting_service) {
469 base::Value reporting_value = reporting_service->StatusAsValue();
470 NetworkErrorLoggingService* network_error_logging_service =
471 context->network_error_logging_service();
472 if (network_error_logging_service) {
473 reporting_value.GetDict().Set(
474 "networkErrorLogging",
475 network_error_logging_service->StatusAsValue());
476 }
477 net_info_dict.Set(kNetInfoReporting, std::move(reporting_value));
478 } else {
479 net_info_dict.Set(kNetInfoReporting,
480 base::Value::Dict().Set("reportingEnabled", false));
481 }
482
483 #else // BUILDFLAG(ENABLE_REPORTING)
484 net_info_dict.Set(kNetInfoReporting,
485 base::Value::Dict().Set("reportingEnabled", false));
486 #endif // BUILDFLAG(ENABLE_REPORTING)
487 }
488
489 // Log currently-active field trials. New trials may have been enabled since
490 // the start of this browser session (crbug.com/1133396).
491 net_info_dict.Set(kNetInfoFieldTrials, GetActiveFieldTrialList());
492
493 return net_info_dict;
494 }
495
CreateNetLogEntriesForActiveObjects(const std::set<URLRequestContext * > & contexts,NetLog::ThreadSafeObserver * observer)496 NET_EXPORT void CreateNetLogEntriesForActiveObjects(
497 const std::set<URLRequestContext*>& contexts,
498 NetLog::ThreadSafeObserver* observer) {
499 // Put together the list of all requests.
500 std::vector<const URLRequest*> requests;
501 for (auto* context : contexts) {
502 // May only be called on the context's thread.
503 context->AssertCalledOnValidThread();
504 // Contexts should all be using the same NetLog.
505 DCHECK_EQ((*contexts.begin())->net_log(), context->net_log());
506 for (const URLRequest* request : *context->url_requests()) {
507 requests.push_back(request);
508 }
509 }
510
511 // Sort by creation time.
512 std::sort(requests.begin(), requests.end(), RequestCreatedBefore);
513
514 // Create fake events.
515 for (auto* request : requests) {
516 NetLogEntry entry(NetLogEventType::REQUEST_ALIVE,
517 request->net_log().source(), NetLogEventPhase::BEGIN,
518 request->creation_time(), request->GetStateAsValue());
519 observer->OnAddEntry(entry);
520 }
521 }
522
523 } // namespace net
524