diff options
author | eroman@chromium.org <eroman@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2010-04-09 04:34:47 +0000 |
---|---|---|
committer | eroman@chromium.org <eroman@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2010-04-09 04:34:47 +0000 |
commit | 1f0e32b947057d19c6772587e72799f2644119f1 (patch) | |
tree | 57fcee3c417e40c87cb81bf316ccef45a1878e0f | |
parent | 3ef4bc6355b48c74928feefd8bbaff501bb8d59f (diff) | |
download | chromium_src-1f0e32b947057d19c6772587e72799f2644119f1.zip chromium_src-1f0e32b947057d19c6772587e72799f2644119f1.tar.gz chromium_src-1f0e32b947057d19c6772587e72799f2644119f1.tar.bz2 |
Add support for attaching custom parameters to NetLog events.
BUG=37421
Review URL: http://codereview.chromium.org/1556018
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@44057 0039d316-1c4b-4281-b951-d872f2087c98
24 files changed, 525 insertions, 398 deletions
diff --git a/chrome/browser/dom_ui/net_internals_ui.cc b/chrome/browser/dom_ui/net_internals_ui.cc index a932d75..e72ef12 100644 --- a/chrome/browser/dom_ui/net_internals_ui.cc +++ b/chrome/browser/dom_ui/net_internals_ui.cc @@ -152,7 +152,11 @@ class NetInternalsMessageHandler::IOThreadImpl void OnClearHostResolverCache(const Value* value); // ChromeNetLog::Observer implementation: - virtual void OnAddEntry(const net::NetLog::Entry& entry); + virtual void OnAddEntry(net::NetLog::EventType type, + const base::TimeTicks& time, + const net::NetLog::Source& source, + net::NetLog::EventPhase phase, + net::NetLog::EventParameters* extra_parameters); private: class CallbackHelper; @@ -399,18 +403,6 @@ void NetInternalsMessageHandler::IOThreadImpl::OnRendererReady( CallJavascriptFunction(L"g_browser.receivedLogSourceTypeConstants", dict); } - // Tell the javascript about the relationship between entry type enums and - // their symbolic name. - { - DictionaryValue* dict = new DictionaryValue(); - - dict->SetInteger(L"TYPE_EVENT", net::NetLog::Entry::TYPE_EVENT); - dict->SetInteger(L"TYPE_STRING", net::NetLog::Entry::TYPE_STRING); - dict->SetInteger(L"TYPE_ERROR_CODE", net::NetLog::Entry::TYPE_ERROR_CODE); - - CallJavascriptFunction(L"g_browser.receivedLogEntryTypeConstants", dict); - } - // Tell the javascript how the "time ticks" values we have given it relate to // actual system times. (We used time ticks throughout since they are stable // across system clock changes). @@ -576,53 +568,34 @@ void NetInternalsMessageHandler::IOThreadImpl::OnClearHostResolverCache( } void NetInternalsMessageHandler::IOThreadImpl::OnAddEntry( - const net::NetLog::Entry& entry) { + net::NetLog::EventType type, + const base::TimeTicks& time, + const net::NetLog::Source& source, + net::NetLog::EventPhase phase, + net::NetLog::EventParameters* extra_parameters) { DCHECK(is_observing_log_); // JSONify the NetLog::Entry. // TODO(eroman): Need a better format for this. DictionaryValue* entry_dict = new DictionaryValue(); - // Set the entry type. - { - net::NetLog::Entry::Type entry_type = entry.type; - if (entry_type == net::NetLog::Entry::TYPE_STRING_LITERAL) - entry_type = net::NetLog::Entry::TYPE_STRING; - entry_dict->SetInteger(L"type", static_cast<int>(entry_type)); - } - // Set the entry time. (Note that we send it as a string since integers // might overflow). - entry_dict->SetString(L"time", TickCountToString(entry.time)); + entry_dict->SetString(L"time", TickCountToString(time)); // Set the entry source. DictionaryValue* source_dict = new DictionaryValue(); - source_dict->SetInteger(L"id", entry.source.id); - source_dict->SetInteger(L"type", static_cast<int>(entry.source.type)); + source_dict->SetInteger(L"id", source.id); + source_dict->SetInteger(L"type", static_cast<int>(source.type)); entry_dict->Set(L"source", source_dict); - // Set the event info (if it is an event entry). - if (entry.type == net::NetLog::Entry::TYPE_EVENT) { - DictionaryValue* event_dict = new DictionaryValue(); - event_dict->SetInteger(L"type", static_cast<int>(entry.event.type)); - event_dict->SetInteger(L"phase", static_cast<int>(entry.event.phase)); - entry_dict->Set(L"event", event_dict); - } - - // Add the string information (events my have a string too, due to current - // hacks). - if (entry.type == net::NetLog::Entry::TYPE_STRING || !entry.string.empty()) { - entry_dict->SetString(L"string", entry.string); - } - - // Treat string literals the same as strings. - if (entry.type == net::NetLog::Entry::TYPE_STRING_LITERAL) { - entry_dict->SetString(L"string", entry.literal); - } + // Set the event info. + entry_dict->SetInteger(L"type", static_cast<int>(type)); + entry_dict->SetInteger(L"phase", static_cast<int>(phase)); - if (entry.type == net::NetLog::Entry::TYPE_ERROR_CODE) { - entry_dict->SetInteger(L"error_code", entry.error_code); - } + // Set the event-specific parameters. + if (extra_parameters) + entry_dict->SetString(L"extra_parameters", extra_parameters->ToString()); CallJavascriptFunction(L"g_browser.receivedLogEntry", entry_dict); } diff --git a/chrome/browser/net/chrome_net_log.cc b/chrome/browser/net/chrome_net_log.cc index 6abf58a..efb27be 100644 --- a/chrome/browser/net/chrome_net_log.cc +++ b/chrome/browser/net/chrome_net_log.cc @@ -23,11 +23,16 @@ ChromeNetLog::~ChromeNetLog() { RemoveObserver(passive_collector_.get()); } -void ChromeNetLog::AddEntry(const Entry& entry) { +void ChromeNetLog::AddEntry(EventType type, + const base::TimeTicks& time, + const Source& source, + EventPhase phase, + EventParameters* extra_parameters) { DCHECK(ChromeThread::CurrentlyOn(ChromeThread::IO)); // Notify all of the log observers. - FOR_EACH_OBSERVER(Observer, observers_, OnAddEntry(entry)); + FOR_EACH_OBSERVER(Observer, observers_, + OnAddEntry(type, time, source, phase, extra_parameters)); } int ChromeNetLog::NextID() { diff --git a/chrome/browser/net/chrome_net_log.h b/chrome/browser/net/chrome_net_log.h index d27c8d0..7a50eca 100644 --- a/chrome/browser/net/chrome_net_log.h +++ b/chrome/browser/net/chrome_net_log.h @@ -25,14 +25,22 @@ class ChromeNetLog : public net::NetLog { class Observer { public: virtual ~Observer() {} - virtual void OnAddEntry(const Entry& entry) = 0; + virtual void OnAddEntry(EventType type, + const base::TimeTicks& time, + const Source& source, + EventPhase phase, + EventParameters* extra_parameters) = 0; }; ChromeNetLog(); ~ChromeNetLog(); // NetLog implementation: - virtual void AddEntry(const Entry& entry); + virtual void AddEntry(EventType type, + const base::TimeTicks& time, + const Source& source, + EventPhase phase, + EventParameters* extra_parameters); virtual int NextID(); virtual bool HasListener() const; diff --git a/chrome/browser/net/passive_log_collector.cc b/chrome/browser/net/passive_log_collector.cc index 33cc8d1..2b73885 100644 --- a/chrome/browser/net/passive_log_collector.cc +++ b/chrome/browser/net/passive_log_collector.cc @@ -21,7 +21,7 @@ bool OrderBySourceID(const PassiveLogCollector::RequestInfo& a, return a.entries[0].source.id < b.entries[0].source.id; } -void AddEntryToRequestInfo(const net::NetLog::Entry& entry, +void AddEntryToRequestInfo(const net::CapturingNetLog::Entry& entry, bool is_unbounded, PassiveLogCollector::RequestInfo* out_info) { // Start dropping new entries when the log has gotten too big. @@ -54,7 +54,16 @@ PassiveLogCollector::PassiveLogCollector() PassiveLogCollector::~PassiveLogCollector() { } -void PassiveLogCollector::OnAddEntry(const net::NetLog::Entry& entry) { +void PassiveLogCollector::OnAddEntry( + net::NetLog::EventType type, + const base::TimeTicks& time, + const net::NetLog::Source& source, + net::NetLog::EventPhase phase, + net::NetLog::EventParameters* extra_parameters) { + // Package the parameters into a single struct for convenience. + net::CapturingNetLog::Entry entry(type, time, source, phase, + extra_parameters); + switch (entry.source.type) { case net::NetLog::SOURCE_URL_REQUEST: url_request_tracker_.OnAddEntry(entry); @@ -92,7 +101,7 @@ PassiveLogCollector::RequestTrackerBase::RequestTrackerBase( } void PassiveLogCollector::RequestTrackerBase::OnAddEntry( - const net::NetLog::Entry& entry) { + const net::CapturingNetLog::Entry& entry) { RequestInfo& info = live_requests_[entry.source.id]; Action result = DoAddEntry(entry, &info); @@ -222,15 +231,14 @@ PassiveLogCollector::ConnectJobTracker::ConnectJobTracker() PassiveLogCollector::RequestTrackerBase::Action PassiveLogCollector::ConnectJobTracker::DoAddEntry( - const net::NetLog::Entry& entry, + const net::CapturingNetLog::Entry& entry, RequestInfo* out_info) { // Save the entry (possibly truncating). AddEntryToRequestInfo(entry, is_unbounded(), out_info); // If this is the end of the connect job, move the request to the graveyard. - if (entry.type == net::NetLog::Entry::TYPE_EVENT && - entry.event.type == net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB && - entry.event.phase == net::NetLog::PHASE_END) { + if (entry.type == net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB && + entry.phase == net::NetLog::PHASE_END) { return ACTION_MOVE_TO_GRAVEYARD; } @@ -252,11 +260,10 @@ PassiveLogCollector::RequestTracker::RequestTracker( PassiveLogCollector::RequestTrackerBase::Action PassiveLogCollector::RequestTracker::DoAddEntry( - const net::NetLog::Entry& entry, + const net::CapturingNetLog::Entry& entry, RequestInfo* out_info) { - if (entry.type == net::NetLog::Entry::TYPE_EVENT && - entry.event.type == net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID) { + if (entry.type == net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID) { // If this was notification that a ConnectJob was bound to the request, // copy all the logged data for that ConnectJob. AddConnectJobInfo(entry, out_info); @@ -266,22 +273,19 @@ PassiveLogCollector::RequestTracker::DoAddEntry( } // If this was the start of a URLRequest/SocketStream, extract the URL. - if (out_info->entries.size() == 1 && - entry.type == net::NetLog::Entry::TYPE_EVENT && - entry.event.type == net::NetLog::TYPE_REQUEST_ALIVE && - entry.event.phase == net::NetLog::PHASE_BEGIN) { - out_info->url = entry.string; - out_info->entries[0].string = std::string(); - - // Paranoia check: truncate the URL if it is really big. - if (out_info->url.size() > kMaxGraveyardURLSize) - out_info->url = out_info->url.substr(0, kMaxGraveyardURLSize); + // Note: we look at the first *two* entries, since the outer REQUEST_ALIVE + // doesn't actually contain any data. + if (out_info->url.empty() && out_info->entries.size() <= 2 && + entry.phase == net::NetLog::PHASE_BEGIN && entry.extra_parameters && + (entry.type == net::NetLog::TYPE_URL_REQUEST_START || + entry.type == net::NetLog::TYPE_SOCKET_STREAM_CONNECT)) { + out_info->url = static_cast<net::NetLogStringParameter*>( + entry.extra_parameters.get())->value(); } // If the request has ended, move it to the graveyard. - if (entry.type == net::NetLog::Entry::TYPE_EVENT && - entry.event.type == net::NetLog::TYPE_REQUEST_ALIVE && - entry.event.phase == net::NetLog::PHASE_END) { + if (entry.type == net::NetLog::TYPE_REQUEST_ALIVE && + entry.phase == net::NetLog::PHASE_END) { if (StartsWithASCII(out_info->url, "chrome://", false)) { // Avoid sending "chrome://" requests to the graveyard, since it just // adds to clutter. @@ -294,15 +298,15 @@ PassiveLogCollector::RequestTracker::DoAddEntry( } void PassiveLogCollector::RequestTracker::AddConnectJobInfo( - const net::NetLog::Entry& entry, + const net::CapturingNetLog::Entry& entry, RequestInfo* live_entry) { // We have just been notified of which ConnectJob the // URLRequest/SocketStream was assigned. Lookup all the data we captured // for the ConnectJob, and append it to the URLRequest/SocketStream's // RequestInfo. - // TODO(eroman): This should NOT be plumbed through via |error_code| ! - int connect_job_id = entry.error_code; + int connect_job_id = static_cast<net::NetLogIntegerParameter*>( + entry.extra_parameters.get())->value(); const RequestInfo* connect_job_info = connect_job_tracker_->GetRequestInfoFromGraveyard(connect_job_id); @@ -313,9 +317,10 @@ void PassiveLogCollector::RequestTracker::AddConnectJobInfo( } else { // If we couldn't find the information for the ConnectJob, append a // generic message instead. - net::NetLog::Entry e(entry); - e.type = net::NetLog::Entry::TYPE_STRING; - e.string = StringPrintf("Used ConnectJob id=%d", connect_job_id); + net::CapturingNetLog::Entry e(entry); + e.type = net::NetLog::TYPE_TODO_STRING; + e.extra_parameters = new net::NetLogStringParameter( + StringPrintf("Used ConnectJob id=%d", connect_job_id)); AddEntryToRequestInfo(e, is_unbounded(), live_entry); } } @@ -327,10 +332,9 @@ void PassiveLogCollector::RequestTracker::AddConnectJobInfo( PassiveLogCollector::InitProxyResolverTracker::InitProxyResolverTracker() {} void PassiveLogCollector::InitProxyResolverTracker::OnAddEntry( - const net::NetLog::Entry& entry) { - if (entry.type == net::NetLog::Entry::TYPE_EVENT && - entry.event.type == net::NetLog::TYPE_INIT_PROXY_RESOLVER && - entry.event.phase == net::NetLog::PHASE_BEGIN) { + const net::CapturingNetLog::Entry& entry) { + if (entry.type == net::NetLog::TYPE_INIT_PROXY_RESOLVER && + entry.phase == net::NetLog::PHASE_BEGIN) { // If this is the start of a new InitProxyResolver, overwrite the old data. entries_.clear(); entries_.push_back(entry); diff --git a/chrome/browser/net/passive_log_collector.h b/chrome/browser/net/passive_log_collector.h index cfa0d21..cb4395d 100644 --- a/chrome/browser/net/passive_log_collector.h +++ b/chrome/browser/net/passive_log_collector.h @@ -16,7 +16,7 @@ class PassiveLogCollector : public ChromeNetLog::Observer { struct RequestInfo { RequestInfo() : num_entries_truncated(0) {} std::string url; - std::vector<net::NetLog::Entry> entries; + net::CapturingNetLog::EntryList entries; size_t num_entries_truncated; }; @@ -28,7 +28,7 @@ class PassiveLogCollector : public ChromeNetLog::Observer { public: explicit RequestTrackerBase(size_t max_graveyard_size); - void OnAddEntry(const net::NetLog::Entry& entry); + void OnAddEntry(const net::CapturingNetLog::Entry& entry); RequestInfoList GetLiveRequests() const; void ClearRecentlyDeceased(); @@ -50,7 +50,7 @@ class PassiveLogCollector : public ChromeNetLog::Observer { // Updates |out_info| with the information from |entry|. Returns an action // to perform for this map entry on completion. - virtual Action DoAddEntry(const net::NetLog::Entry& entry, + virtual Action DoAddEntry(const net::CapturingNetLog::Entry& entry, RequestInfo* out_info) = 0; bool is_unbounded() const { return is_unbounded_; } @@ -58,9 +58,6 @@ class PassiveLogCollector : public ChromeNetLog::Observer { private: typedef base::hash_map<int, RequestInfo> SourceIDToInfoMap; - bool HandleNotificationOfConnectJobID(const net::NetLog::Entry& entry, - RequestInfo* live_entry); - void RemoveFromLiveRequests(int source_id); void InsertIntoGraveyard(const RequestInfo& info); @@ -81,7 +78,7 @@ class PassiveLogCollector : public ChromeNetLog::Observer { ConnectJobTracker(); protected: - virtual Action DoAddEntry(const net::NetLog::Entry& entry, + virtual Action DoAddEntry(const net::CapturingNetLog::Entry& entry, RequestInfo* out_info); private: DISALLOW_COPY_AND_ASSIGN(ConnectJobTracker); @@ -96,13 +93,13 @@ class PassiveLogCollector : public ChromeNetLog::Observer { explicit RequestTracker(ConnectJobTracker* connect_job_tracker); protected: - virtual Action DoAddEntry(const net::NetLog::Entry& entry, + virtual Action DoAddEntry(const net::CapturingNetLog::Entry& entry, RequestInfo* out_info); private: // Searches through |connect_job_tracker_| for information on the // ConnectJob specified in |entry|, and appends it to |live_entry|. - void AddConnectJobInfo(const net::NetLog::Entry& entry, + void AddConnectJobInfo(const net::CapturingNetLog::Entry& entry, RequestInfo* live_entry); ConnectJobTracker* connect_job_tracker_; @@ -115,14 +112,14 @@ class PassiveLogCollector : public ChromeNetLog::Observer { public: InitProxyResolverTracker(); - void OnAddEntry(const net::NetLog::Entry& entry); + void OnAddEntry(const net::CapturingNetLog::Entry& entry); - const std::vector<net::NetLog::Entry>& entries() const { + const net::CapturingNetLog::EntryList& entries() const { return entries_; } private: - std::vector<net::NetLog::Entry> entries_; + net::CapturingNetLog::EntryList entries_; DISALLOW_COPY_AND_ASSIGN(InitProxyResolverTracker); }; @@ -130,7 +127,11 @@ class PassiveLogCollector : public ChromeNetLog::Observer { ~PassiveLogCollector(); // Observer implementation: - virtual void OnAddEntry(const net::NetLog::Entry& entry); + virtual void OnAddEntry(net::NetLog::EventType type, + const base::TimeTicks& time, + const net::NetLog::Source& source, + net::NetLog::EventPhase phase, + net::NetLog::EventParameters* extra_parameters); // Clears all of the passively logged data. void Clear(); diff --git a/chrome/browser/net/passive_log_collector_unittest.cc b/chrome/browser/net/passive_log_collector_unittest.cc index ae18839..9c31ee0 100644 --- a/chrome/browser/net/passive_log_collector_unittest.cc +++ b/chrome/browser/net/passive_log_collector_unittest.cc @@ -16,31 +16,28 @@ typedef PassiveLogCollector::RequestInfoList RequestInfoList; const net::NetLog::SourceType kSourceType = net::NetLog::SOURCE_NONE; -net::NetLog::Entry MakeStartLogEntryWithURL(int source_id, - const std::string& url) { - net::NetLog::Entry entry; - entry.source.type = kSourceType; - entry.source.id = source_id; - entry.type = net::NetLog::Entry::TYPE_EVENT; - entry.event = net::NetLog::Event(net::NetLog::TYPE_REQUEST_ALIVE, - net::NetLog::PHASE_BEGIN); - entry.string = url; - return entry; +net::CapturingNetLog::Entry MakeStartLogEntryWithURL(int source_id, + const std::string& url) { + return net::CapturingNetLog::Entry( + net::NetLog::TYPE_URL_REQUEST_START, + base::TimeTicks(), + net::NetLog::Source(kSourceType, source_id), + net::NetLog::PHASE_BEGIN, + new net::NetLogStringParameter(url)); } -net::NetLog::Entry MakeStartLogEntry(int source_id) { +net::CapturingNetLog::Entry MakeStartLogEntry(int source_id) { return MakeStartLogEntryWithURL(source_id, StringPrintf("http://req%d", source_id)); } -net::NetLog::Entry MakeEndLogEntry(int source_id) { - net::NetLog::Entry entry; - entry.source.type = kSourceType; - entry.source.id = source_id; - entry.type = net::NetLog::Entry::TYPE_EVENT; - entry.event = net::NetLog::Event(net::NetLog::TYPE_REQUEST_ALIVE, - net::NetLog::PHASE_END); - return entry; +net::CapturingNetLog::Entry MakeEndLogEntry(int source_id) { + return net::CapturingNetLog::Entry( + net::NetLog::TYPE_REQUEST_ALIVE, + base::TimeTicks(), + net::NetLog::Source(kSourceType, source_id), + net::NetLog::PHASE_END, + NULL); } static const int kMaxNumLoadLogEntries = 1; @@ -134,22 +131,6 @@ TEST(RequestTrackerTest, GraveyardUnbounded) { } } -// Check that very long URLs are truncated. -TEST(RequestTrackerTest, GraveyardURLBounded) { - RequestTracker tracker(NULL); - EXPECT_FALSE(tracker.IsUnbounded()); - - std::string big_url("http://"); - big_url.resize(2 * RequestTracker::kMaxGraveyardURLSize, 'x'); - - tracker.OnAddEntry(MakeStartLogEntryWithURL(1, big_url)); - tracker.OnAddEntry(MakeEndLogEntry(1)); - - ASSERT_EQ(1u, tracker.GetRecentlyDeceased().size()); - EXPECT_EQ(RequestTracker::kMaxGraveyardURLSize, - tracker.GetRecentlyDeceased()[0].url.size()); -} - // Check that we exclude "chrome://" URLs from being saved into the recent // requests list (graveyard). TEST(RequestTrackerTest, GraveyardIsFiltered) { diff --git a/chrome/browser/net/view_net_internals_job_factory.cc b/chrome/browser/net/view_net_internals_job_factory.cc index 722559a..aa63fe0 100644 --- a/chrome/browser/net/view_net_internals_job_factory.cc +++ b/chrome/browser/net/view_net_internals_job_factory.cc @@ -447,7 +447,7 @@ class HostResolverTraceSubSection : public SubSection { DrawCommandButton("Enable tracing", "hostresolver-trace-enable", out); } - std::vector<net::NetLog::Entry> entries; + net::CapturingNetLog::EntryList entries; if (resolver->GetRequestsTrace(&entries)) { out->append( "<p>To make sense of this trace, process it with the Python script " diff --git a/chrome/browser/resources/net_internals/loggrouper.js b/chrome/browser/resources/net_internals/loggrouper.js index a3cf7a5..39ff96c 100644 --- a/chrome/browser/resources/net_internals/loggrouper.js +++ b/chrome/browser/resources/net_internals/loggrouper.js @@ -20,13 +20,11 @@ function LogGroupEntry(origEntry, index) { } LogGroupEntry.prototype.isBegin = function() { - return this.orig.type == LogEntryType.TYPE_EVENT && - this.orig.event.phase == LogEventPhase.PHASE_BEGIN; + return this.orig.phase == LogEventPhase.PHASE_BEGIN; }; LogGroupEntry.prototype.isEnd = function() { - return this.orig.type == LogEntryType.TYPE_EVENT && - this.orig.event.phase == LogEventPhase.PHASE_END + return this.orig.phase == LogEventPhase.PHASE_END }; LogGroupEntry.prototype.getDepth = function() { @@ -41,7 +39,7 @@ LogGroupEntry.prototype.getDepth = function() { function findParentIndex(parentStack, eventType) { for (var i = parentStack.length - 1; i >= 0; --i) { - if (parentStack[i].orig.event.type == eventType) + if (parentStack[i].orig.type == eventType) return i; } return -1; @@ -67,7 +65,7 @@ LogGroupEntry.createArrayFrom = function(origEntries) { if (groupEntry.isEnd()) { // Walk up the parent stack to find the corresponding BEGIN for this END. var parentIndex = - findParentIndex(parentStack, groupEntry.orig.event.type); + findParentIndex(parentStack, groupEntry.orig.type); if (parentIndex == -1) { // Unmatched end. diff --git a/chrome/browser/resources/net_internals/logviewpainter.js b/chrome/browser/resources/net_internals/logviewpainter.js index 8a068f7..bfabd30 100644 --- a/chrome/browser/resources/net_internals/logviewpainter.js +++ b/chrome/browser/resources/net_internals/logviewpainter.js @@ -68,31 +68,28 @@ function makeLoadLogTable_(node, entries) { mainCell.style.paddingLeft = (INDENTATION_PX * entry.getDepth()) + "px"; - if (entry.orig.type == LogEntryType.TYPE_EVENT) { - addTextNode(mainCell, getTextForEvent(entry)); - - // Get the elapsed time. - if (entry.isBegin()) { - addTextNode(dtLabelCell, '[dt='); - - // Definite time. - if (entry.end) { - var dt = entry.end.orig.time - entry.orig.time; - addTextNode(dtCell, dt + ']'); - } else { - addTextNode(dtCell, '?]'); - } + addTextNode(mainCell, getTextForEvent(entry)); + + // Get the elapsed time. + if (entry.isBegin()) { + addTextNode(dtLabelCell, '[dt='); + + // Definite time. + if (entry.end) { + var dt = entry.end.orig.time - entry.orig.time; + addTextNode(dtCell, dt + ']'); + } else { + addTextNode(dtCell, '?]'); } } else { mainCell.colSpan = '3'; - if (entry.orig.type == LogEntryType.TYPE_STRING) { - addTextNode(mainCell, entry.orig.string); - } else if (entry.orig.type == LogEntryType.TYPE_ERROR_CODE) { - // TODO(eroman): print symbolic name of error code. - addTextNode(mainCell, "Network error: " + entry.orig.error_code); - } else { - addTextNode(mainCell, "Unrecognized entry type: " + entry.orig.type); - } + } + + // Output the extra parameters. + // TODO(eroman): Do type-specific formatting. + if (entry.orig.extra_parameters != undefined) { + addNode(mainCell, 'br'); + addTextNode(mainCell, 'params: ' + entry.orig.extra_parameters); } } } @@ -108,7 +105,7 @@ function getTextForEvent(entry) { text = '.'; } - text += getKeyWithValue(LogEventType, entry.orig.event.type); + text += getKeyWithValue(LogEventType, entry.orig.type); return text; } diff --git a/chrome/browser/resources/net_internals/main.js b/chrome/browser/resources/net_internals/main.js index 3ab30eb..2d1fa2f 100644 --- a/chrome/browser/resources/net_internals/main.js +++ b/chrome/browser/resources/net_internals/main.js @@ -5,7 +5,6 @@ /** * Dictionary of constants (initialized by browser). */ -var LogEntryType = null; var LogEventType = null; var LogEventPhase = null; var LogSourceType = null; @@ -189,10 +188,6 @@ function(constantsMap) { LogSourceType = constantsMap; }; -BrowserBridge.prototype.receivedLogEntryTypeConstants = function(constantsMap) { - LogEntryType = constantsMap; -}; - BrowserBridge.prototype.receivedTimeTickOffset = function(timeTickOffset) { this.timeTickOffset_ = timeTickOffset; }; diff --git a/chrome/browser/resources/net_internals/sourceentry.js b/chrome/browser/resources/net_internals/sourceentry.js index 72d3a44..8385e91 100644 --- a/chrome/browser/resources/net_internals/sourceentry.js +++ b/chrome/browser/resources/net_internals/sourceentry.js @@ -61,9 +61,12 @@ SourceEntry.prototype.setFilterStyles = function(isMatchedByFilter) { }; SourceEntry.prototype.update = function(logEntry) { + var prevStartEntry = this.getStartEntry_(); this.entries_.push(logEntry); + var curStartEntry = this.getStartEntry_(); - if (this.entries_.length == 1) { + // If we just got the first entry for this source. + if (!prevStartEntry && curStartEntry) { this.createRow_(); // Only apply the filter during the first update. @@ -149,13 +152,28 @@ SourceEntry.prototype.createRow_ = function() { }; SourceEntry.prototype.getDescription = function() { - var e = this.entries_[0]; - if (e.type == LogEntryType.TYPE_EVENT && - e.event.phase == LogEventPhase.PHASE_BEGIN && - e.string != undefined) { - return e.string; // The URL / hostname / whatever. - } - return ''; + var e = this.getStartEntry_(); + if (!e || e.extra_parameters == undefined) + return ''; + return e.extra_parameters; // The URL / hostname / whatever. +}; + +/** + * Returns the starting entry for this source. Conceptually this is the + * first entry that was logged to this source. However, we skip over the + * TYPE_REQUEST_ALIVE entries which wrap TYPE_URL_REQUEST_START / + * TYPE_SOCKET_STREAM_CONNECT. + * + * TODO(eroman): Get rid of TYPE_REQUEST_ALIVE so this isn't necessary. + */ +SourceEntry.prototype.getStartEntry_ = function() { + if (this.entries_.length < 1) + return undefined; + if (this.entries_[0].type != LogEventType.REQUEST_ALIVE) + return this.entries_[0]; + if (this.entries_.length < 2) + return undefined; + return this.entries_[1]; }; SourceEntry.prototype.getLogEntries = function() { diff --git a/net/base/host_resolver_impl.cc b/net/base/host_resolver_impl.cc index 4fe2ccd..1f43c60 100644 --- a/net/base/host_resolver_impl.cc +++ b/net/base/host_resolver_impl.cc @@ -163,16 +163,16 @@ class HostResolverImpl::RequestsTrace RequestsTrace() {} void Add(const std::string& msg) { - NetLog::Entry entry; - entry.type = NetLog::Entry::TYPE_STRING; - entry.time = base::TimeTicks::Now(); - entry.string = msg; - + CapturingNetLog::Entry entry(NetLog::TYPE_TODO_STRING, + base::TimeTicks::Now(), + NetLog::Source(), + NetLog::PHASE_NONE, + new NetLogStringParameter(msg)); AutoLock l(lock_); entries_.push_back(entry); } - void Get(std::vector<NetLog::Entry>* entries) { + void Get(CapturingNetLog::EntryList* entries) { AutoLock l(lock_); *entries = entries_; } @@ -184,7 +184,7 @@ class HostResolverImpl::RequestsTrace private: Lock lock_; - std::vector<NetLog::Entry> entries_; + CapturingNetLog::EntryList entries_; }; //----------------------------------------------------------------------------- @@ -912,7 +912,7 @@ bool HostResolverImpl::IsRequestsTracingEnabled() const { return !!requests_trace_; // Cast to bool. } -bool HostResolverImpl::GetRequestsTrace(std::vector<NetLog::Entry>* entries) { +bool HostResolverImpl::GetRequestsTrace(CapturingNetLog::EntryList* entries) { if (!requests_trace_) return false; requests_trace_->Get(entries); diff --git a/net/base/host_resolver_impl.h b/net/base/host_resolver_impl.h index 1a87dfe..4814921 100644 --- a/net/base/host_resolver_impl.h +++ b/net/base/host_resolver_impl.h @@ -113,7 +113,7 @@ class HostResolverImpl : public HostResolver { bool IsRequestsTracingEnabled() const; // Gets a copy of the requests trace log. - bool GetRequestsTrace(std::vector<NetLog::Entry>* entries); + bool GetRequestsTrace(CapturingNetLog::EntryList* entries); // Applies a set of constraints for requests that belong to the specified // pool. NOTE: Don't call this after requests have been already been started. diff --git a/net/base/net_log.cc b/net/base/net_log.cc index 6bb9297..1ebdfdb 100644 --- a/net/base/net_log.cc +++ b/net/base/net_log.cc @@ -4,6 +4,7 @@ #include "net/base/net_log.h" #include "base/logging.h" +#include "base/string_util.h" namespace net { @@ -26,9 +27,23 @@ std::vector<NetLog::EventType> NetLog::GetAllEventTypes() { return types; } -void BoundNetLog::AddEntry(const NetLog::Entry& entry) const { - if (net_log_) - net_log_->AddEntry(entry); +void BoundNetLog::AddEntry(NetLog::EventType type, + NetLog::EventPhase phase, + NetLog::EventParameters* extra_parameters) const { + if (net_log_) { + net_log_->AddEntry(type, base::TimeTicks::Now(), source_, phase, + extra_parameters); + } +} + +void BoundNetLog::AddEntryWithTime( + NetLog::EventType type, + const base::TimeTicks& time, + NetLog::EventPhase phase, + NetLog::EventParameters* extra_parameters) const { + if (net_log_) { + net_log_->AddEntry(type, time, source_, phase, extra_parameters); + } } bool BoundNetLog::HasListener() const { @@ -38,91 +53,72 @@ bool BoundNetLog::HasListener() const { } void BoundNetLog::AddEvent(NetLog::EventType event_type) const { - if (net_log_) { - NetLog::Entry entry; - entry.source = source_; - entry.type = NetLog::Entry::TYPE_EVENT; - entry.time = base::TimeTicks::Now(); - entry.event = NetLog::Event(event_type, NetLog::PHASE_NONE); - AddEntry(entry); - } + AddEventWithParameters(event_type, NULL); +} + +void BoundNetLog::AddEventWithParameters( + NetLog::EventType event_type, + NetLog::EventParameters* params) const { + AddEntry(event_type, NetLog::PHASE_NONE, params); +} + +void BoundNetLog::AddEventWithInteger(NetLog::EventType event_type, + int integer) const { + scoped_refptr<NetLog::EventParameters> params = + new NetLogIntegerParameter(integer); + AddEventWithParameters(event_type, params); } void BoundNetLog::BeginEvent(NetLog::EventType event_type) const { - if (net_log_) { - NetLog::Entry entry; - entry.source = source_; - entry.type = NetLog::Entry::TYPE_EVENT; - entry.time = base::TimeTicks::Now(); - entry.event = NetLog::Event(event_type, NetLog::PHASE_BEGIN); - AddEntry(entry); - } + BeginEventWithParameters(event_type, NULL); +} + +void BoundNetLog::BeginEventWithParameters( + NetLog::EventType event_type, + NetLog::EventParameters* params) const { + AddEntry(event_type, NetLog::PHASE_BEGIN, params); } void BoundNetLog::BeginEventWithString(NetLog::EventType event_type, const std::string& string) const { - NetLog::Entry entry; - entry.source = source_; - entry.type = NetLog::Entry::TYPE_EVENT; - entry.time = base::TimeTicks::Now(); - entry.event = NetLog::Event(event_type, NetLog::PHASE_BEGIN); - entry.string = string; - AddEntry(entry); + scoped_refptr<NetLog::EventParameters> params = + new NetLogStringParameter(string); + BeginEventWithParameters(event_type, params); } -void BoundNetLog::AddEventWithInteger(NetLog::EventType event_type, - int integer) const { - NetLog::Entry entry; - entry.source = source_; - entry.type = NetLog::Entry::TYPE_EVENT; - entry.time = base::TimeTicks::Now(); - entry.event = NetLog::Event(event_type, NetLog::PHASE_NONE); - entry.error_code = integer; - AddEntry(entry); +void BoundNetLog::EndEvent(NetLog::EventType event_type) const { + EndEventWithParameters(event_type, NULL); } -void BoundNetLog::EndEvent(NetLog::EventType event_type) const { - if (net_log_) { - NetLog::Entry entry; - entry.source = source_; - entry.type = NetLog::Entry::TYPE_EVENT; - entry.time = base::TimeTicks::Now(); - entry.event = NetLog::Event(event_type, NetLog::PHASE_END); - AddEntry(entry); - } +void BoundNetLog::EndEventWithParameters( + NetLog::EventType event_type, + NetLog::EventParameters* params) const { + AddEntry(event_type, NetLog::PHASE_END, params); } -void BoundNetLog::AddStringLiteral(const char* literal) const { - if (net_log_) { - NetLog::Entry entry; - entry.source = source_; - entry.type = NetLog::Entry::TYPE_STRING_LITERAL; - entry.time = base::TimeTicks::Now(); - entry.literal = literal; - AddEntry(entry); - } +void BoundNetLog::EndEventWithInteger(NetLog::EventType event_type, + int integer) const { + scoped_refptr<NetLog::EventParameters> params = + new NetLogIntegerParameter(integer); + EndEventWithParameters(event_type, params); } void BoundNetLog::AddString(const std::string& string) const { - if (net_log_) { - NetLog::Entry entry; - entry.source = source_; - entry.type = NetLog::Entry::TYPE_STRING; - entry.time = base::TimeTicks::Now(); - entry.string = string; - AddEntry(entry); - } + // We pass TYPE_TODO_STRING since we have no event type to associate this + // with. (AddString() is deprecated, and should be replaced with + // AddEventWithParameters()). + scoped_refptr<NetLog::EventParameters> params = + new NetLogStringParameter(string); + AddEventWithParameters(NetLog::TYPE_TODO_STRING, params); } -void BoundNetLog::AddErrorCode(int error) const { - if (net_log_) { - NetLog::Entry entry; - entry.source = source_; - entry.type = NetLog::Entry::TYPE_ERROR_CODE; - entry.time = base::TimeTicks::Now(); - entry.error_code = error; - AddEntry(entry); - } +void BoundNetLog::AddStringLiteral(const char* literal) const { + // We pass TYPE_TODO_STRING_LITERAL since we have no event type to associate + // this with. (AddString() is deprecated, and should be replaced with + // AddEventWithParameters()). + scoped_refptr<NetLog::EventParameters> params = + new NetLogStringLiteralParameter(literal); + AddEventWithParameters(NetLog::TYPE_TODO_STRING_LITERAL, params); } // static @@ -135,7 +131,24 @@ BoundNetLog BoundNetLog::Make(NetLog* net_log, return BoundNetLog(source, net_log); } -void CapturingNetLog::AddEntry(const Entry& entry) { +NetLogStringParameter::NetLogStringParameter(const std::string& value) + : value_(value) { +} + +std::string NetLogIntegerParameter::ToString() const { + return IntToString(value_); +} + +std::string NetLogStringLiteralParameter::ToString() const { + return std::string(value_); +} + +void CapturingNetLog::AddEntry(EventType type, + const base::TimeTicks& time, + const Source& source, + EventPhase phase, + EventParameters* extra_parameters) { + Entry entry(type, time, source, phase, extra_parameters); if (entries_.size() + 1 < max_num_entries_) entries_.push_back(entry); } @@ -154,9 +167,9 @@ void CapturingBoundNetLog::Clear() { void CapturingBoundNetLog::AppendTo(const BoundNetLog& net_log) const { for (size_t i = 0; i < entries().size(); ++i) { - NetLog::Entry entry = entries()[i]; - entry.source = net_log.source(); - net_log.AddEntry(entry); + const CapturingNetLog::Entry& entry = entries()[i]; + net_log.AddEntryWithTime(entry.type, entry.time, entry.phase, + entry.extra_parameters); } } diff --git a/net/base/net_log.h b/net/base/net_log.h index ca83edd..3a85131 100644 --- a/net/base/net_log.h +++ b/net/base/net_log.h @@ -8,6 +8,8 @@ #include <string> #include <vector> +#include "base/basictypes.h" +#include "base/ref_counted.h" #include "base/scoped_ptr.h" #include "base/time.h" #include "net/base/net_log.h" @@ -24,11 +26,26 @@ namespace net { // specific source ID. // // Note that NetLog is NOT THREADSAFE. +// +// ******** The NetLog (and associated logging) is a work in progress ******** +// +// TODO(eroman): Remove the 'const' qualitifer from the BoundNetLog methods. +// TODO(eroman): Remove the AddString() and AddStringLiteral() methods. +// These are a carry-over from old approach. Really, consumers +// should be calling AddEventWithParameters(), and passing a +// custom EventParameters* object that encapsulates all of the +// interesting state. +// TODO(eroman): Remove NetLogUtil. Pretty printing should only be done from +// javascript, and should be very context-aware. +// TODO(eroman): Move Capturing*NetLog to its own file. (And eventually remove +// all the consumers of it). +// TODO(eroman): Make the DNS jobs emit directly into the NetLog. +// TODO(eroman): Start a new Source each time URLRequest redirects +// (simpler to reason about each as a separate entity). +// TODO(eroman): Add the URLRequest load flags to the start entry. + class NetLog { public: - // TODO(eroman): Really, EventType and EventPhase should be - // Event::Type and Event::Phase, to be consisent with Entry. - // But there lots of consumers to change! enum EventType { #define EVENT_TYPE(label) TYPE_ ## label, #include "net/base/net_log_event_type_list.h" @@ -43,14 +60,6 @@ class NetLog { PHASE_END, }; - struct Event { - Event(EventType type, EventPhase phase) : type(type), phase(phase) {} - Event() {} - - EventType type; - EventPhase phase; - }; - // The "source" identifies the entity that generated the log message. enum SourceType { SOURCE_NONE, @@ -71,41 +80,39 @@ class NetLog { int id; }; - // TODO(eroman): generalize the entries so events can specify multiple - // parameters, and TYPE_STRING is rarely needed. - struct Entry { - enum Type { - // This entry describes an event trace. - TYPE_EVENT, - - // This entry describes a network error code that was returned. - TYPE_ERROR_CODE, - - // This entry is a free-form std::string. - TYPE_STRING, + // Base class for associating additional parameters with an event. Log + // observers need to know what specific derivations of EventParameters a + // particular EventType uses, in order to get at the individual components. + class EventParameters : public base::RefCounted<EventParameters> { + public: + EventParameters() {} + virtual ~EventParameters() {} - // This entry is a C-string literal. - TYPE_STRING_LITERAL, - }; + // Serializes the parameters to a string representation (this should be a + // lossless conversion). + virtual std::string ToString() const = 0; - Source source; - - Type type; - base::TimeTicks time; - - // The following is basically a union, only one of them should be - // used depending on what |type| is. - Event event; // valid when (type == TYPE_EVENT). - int error_code; // valid when (type == TYPE_ERROR_CODE). - std::string string; // valid when (type == TYPE_STRING). - const char* literal; // valid when (type == TYPE_STRING_LITERAL). + private: + DISALLOW_COPY_AND_ASSIGN(EventParameters); }; NetLog() {} virtual ~NetLog() {} - // Adds a message to the log. - virtual void AddEntry(const Entry& entry) = 0; + // Emits an event to the log stream. + // |type| - The type of the event. + // |time| - The time when the event occurred. + // |source| - The source that generated the event. + // |phase| - An optional parameter indicating whether this is the start/end + // of an action. + // |extra_parameters| - Optional (may be NULL) parameters for this event. + // The specific subclass of EventParameters is defined + // by the contract for events of this |type|. + virtual void AddEntry(EventType type, + const base::TimeTicks& time, + const Source& source, + EventPhase phase, + EventParameters* extra_parameters) = 0; // Returns a unique ID which can be used as a source ID. virtual int NextID() = 0; @@ -140,20 +147,36 @@ class BoundNetLog { : source_(source), net_log_(net_log) { } - void AddEntry(const NetLog::Entry& entry) const; + void AddEntry(NetLog::EventType type, + NetLog::EventPhase phase, + NetLog::EventParameters* extra_parameters) const; + + void AddEntryWithTime(NetLog::EventType type, + const base::TimeTicks& time, + NetLog::EventPhase phase, + NetLog::EventParameters* extra_parameters) const; // Convenience methods that call through to the NetLog, passing in the // currently bound source. void AddEvent(NetLog::EventType event_type) const; + void AddEventWithParameters(NetLog::EventType event_type, + NetLog::EventParameters* params) const; bool HasListener() const; void BeginEvent(NetLog::EventType event_type) const; + void BeginEventWithParameters(NetLog::EventType event_type, + NetLog::EventParameters* params) const; void BeginEventWithString(NetLog::EventType event_type, const std::string& string) const; void AddEventWithInteger(NetLog::EventType event_type, int integer) const; void EndEvent(NetLog::EventType event_type) const; - void AddStringLiteral(const char* literal) const; + void EndEventWithParameters(NetLog::EventType event_type, + NetLog::EventParameters* params) const; + void EndEventWithInteger(NetLog::EventType event_type, int integer) const; + + // Deprecated: Don't add new dependencies that use these methods. Instead, use + // AddEventWithParameters(). void AddString(const std::string& string) const; - void AddErrorCode(int error) const; + void AddStringLiteral(const char* literal) const; // Helper to create a BoundNetLog given a NetLog and a SourceType. Takes care // of creating a unique source ID, and handles the case of NULL net_log. @@ -167,10 +190,78 @@ class BoundNetLog { NetLog* net_log_; }; +// NetLogStringParameter is a subclass of EventParameters that encapsulates a +// single std::string parameter. +class NetLogStringParameter : public NetLog::EventParameters { + public: + explicit NetLogStringParameter(const std::string& value); + + const std::string& value() const { + return value_; + } + + virtual std::string ToString() const { + return value_; + } + + private: + std::string value_; +}; + +// NetLogIntegerParameter is a subclass of EventParameters that encapsulates a +// single integer parameter. +class NetLogIntegerParameter : public NetLog::EventParameters { + public: + explicit NetLogIntegerParameter(int value) : value_(value) {} + + int value() const { + return value_; + } + + virtual std::string ToString() const; + + private: + const int value_; +}; + +// NetLogStringLiteralParameter is a subclass of EventParameters that +// encapsulates a single string literal parameter. +class NetLogStringLiteralParameter : public NetLog::EventParameters { + public: + explicit NetLogStringLiteralParameter(const char* value) : value_(value) {} + + const char* const value() const { + return value_; + } + + virtual std::string ToString() const; + + private: + const char* const value_; +}; + + // CapturingNetLog is an implementation of NetLog that saves messages to a // bounded buffer. class CapturingNetLog : public NetLog { public: + struct Entry { + Entry(EventType type, + const base::TimeTicks& time, + Source source, + EventPhase phase, + EventParameters* extra_parameters) + : type(type), time(time), source(source), phase(phase), + extra_parameters(extra_parameters) { + } + + EventType type; + base::TimeTicks time; + Source source; + EventPhase phase; + scoped_refptr<EventParameters> extra_parameters; + }; + // Ordered set of entries that were logged. typedef std::vector<Entry> EntryList; @@ -182,7 +273,11 @@ class CapturingNetLog : public NetLog { : next_id_(0), max_num_entries_(max_num_entries) {} // NetLog implementation: - virtual void AddEntry(const Entry& entry); + virtual void AddEntry(EventType type, + const base::TimeTicks& time, + const Source& source, + EventPhase phase, + EventParameters* extra_parameters); virtual int NextID(); virtual bool HasListener() const { return true; } diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h index cee9466..9dc8569 100644 --- a/net/base/net_log_event_type_list.h +++ b/net/base/net_log_event_type_list.h @@ -13,6 +13,11 @@ // log context around it.) EVENT_TYPE(CANCELLED) +// TODO(eroman): These are placeholders used by the deprecated +// BoundNetLog::AddString() / BoundNetLog::AddStringLiteral(). +EVENT_TYPE(TODO_STRING) +EVENT_TYPE(TODO_STRING_LITERAL) + // Marks the creation/destruction of a request (URLRequest or SocketStream). // In the begin phase of this event, the message will contain a string which // is the URL. @@ -139,6 +144,13 @@ EVENT_TYPE(SOCKET_POOL_CONNECT_JOB_ID) // Measures the time between URLRequest::Start() and // URLRequest::ResponseStarted(). +// +// For the BEGIN phase, the |extra_parameters| of the event will be of type +// NetLogStringParameter, and will contain the URL. +// +// For the END phase, the |extra_parameters| of the event will be of type +// NetLogIntegerParameter, and will contain the net error code. Altenately, +// the extra_parameters may be NULL indicating no error code. EVENT_TYPE(URL_REQUEST_START) // ------------------------------------------------------------------------ @@ -227,6 +239,13 @@ EVENT_TYPE(HTTP_STREAM_PARSER_READ_HEADERS) // Measures the time between SocketStream::Connect() and // SocketStream::DidEstablishConnection() +// +// For the BEGIN phase, the |extra_parameters| of the event will be of type +// NetLogStringParameter, and will contain the URL. +// +// For the END phase, the |extra_parameters| of the event will be of type +// NetLogIntegerParameter, and will contain the net error code. Altenately, +// the extra_parameters may be NULL indicating no error code. EVENT_TYPE(SOCKET_STREAM_CONNECT) // A message sent on the SocketStream. diff --git a/net/base/net_log_unittest.h b/net/base/net_log_unittest.h index 39a1f36..b7a6147 100644 --- a/net/base/net_log_unittest.h +++ b/net/base/net_log_unittest.h @@ -30,18 +30,16 @@ inline ::testing::AssertionResult LogContainsEventHelper( size_t j = (i < 0) ? entries.size() + i : i; if (j >= entries.size()) return ::testing::AssertionFailure() << j << " is out of bounds."; - const NetLog::Entry& entry = entries[j]; - if (entry.type != NetLog::Entry::TYPE_EVENT) - return ::testing::AssertionFailure() << "Not a TYPE_EVENT entry"; - if (expected_event != entry.event.type) { + const CapturingNetLog::Entry& entry = entries[j]; + if (expected_event != entry.type) { return ::testing::AssertionFailure() - << "Actual event: " << NetLog::EventTypeToString(entry.event.type) + << "Actual event: " << NetLog::EventTypeToString(entry.type) << ". Expected event: " << NetLog::EventTypeToString(expected_event) << "."; } - if (expected_phase != entry.event.phase) { + if (expected_phase != entry.phase) { return ::testing::AssertionFailure() - << "Actual phase: " << entry.event.phase + << "Actual phase: " << entry.phase << ". Expected phase: " << expected_phase << "."; } if (check_time) { @@ -94,12 +92,12 @@ inline ::testing::AssertionResult LogContainsEndEvent( inline ::testing::AssertionResult LogContainsEntryWithType( const CapturingNetLog::EntryList& entries, int i, // Negative indices are reverse indices. - NetLog::Entry::Type type) { + NetLog::EventType type) { // Negative indices are reverse indices. size_t j = (i < 0) ? entries.size() + i : i; if (j >= entries.size()) return ::testing::AssertionFailure() << j << " is out of bounds."; - const NetLog::Entry& entry = entries[j]; + const CapturingNetLog::Entry& entry = entries[j]; if (entry.type != type) return ::testing::AssertionFailure() << "Type does not match."; return ::testing::AssertionSuccess(); @@ -116,10 +114,9 @@ inline size_t ExpectLogContainsSomewhere( NetLog::EventPhase expected_phase) { size_t i = 0; for (; i < entries.size(); ++i) { - const NetLog::Entry& entry = entries[i]; - if (entry.type == NetLog::Entry::TYPE_EVENT && - entry.event.type == expected_event && - entry.event.phase == expected_phase) + const CapturingNetLog::Entry& entry = entries[i]; + if (entry.type == expected_event && + entry.phase == expected_phase) break; } EXPECT_LT(i, entries.size()); diff --git a/net/base/net_log_util.cc b/net/base/net_log_util.cc index 420fb2d..2bcd907 100644 --- a/net/base/net_log_util.cc +++ b/net/base/net_log_util.cc @@ -13,7 +13,7 @@ namespace { class FormatHelper { public: - std::string ToString(const std::vector<NetLog::Entry>& entries, + std::string ToString(const std::vector<CapturingNetLog::Entry>& entries, size_t num_entries_truncated) { entries_.clear(); @@ -49,6 +49,15 @@ class FormatHelper { int indentation_spaces = entries_[i].indentation * kSpacesPerIndentation; std::string entry_str = GetEntryString(i); + // Hack to better print known event types. + if (entries_[i].log_entry->type == NetLog::TYPE_TODO_STRING || + entries_[i].log_entry->type == NetLog::TYPE_TODO_STRING_LITERAL) { + // Don't display the TODO_STRING type. + entry_str = StringPrintf( + " \"%s\"", + entries_[i].log_entry->extra_parameters->ToString().c_str()); + } + StringAppendF(&result, "t=%s: %s%s", PadStringLeft(GetTimeString(i), max_time_width).c_str(), PadStringLeft("", indentation_spaces).c_str(), @@ -63,6 +72,47 @@ class FormatHelper { PadStringLeft(GetBlockDtString(i), max_dt_width).c_str()); } + // Append any custom parameters. + NetLog::EventParameters* extra_params = + entries_[i].log_entry->extra_parameters; + NetLog::EventType type = entries_[i].log_entry->type; + NetLog::EventPhase phase = entries_[i].log_entry->phase; + + if (type != NetLog::TYPE_TODO_STRING && + type != NetLog::TYPE_TODO_STRING_LITERAL && + extra_params) { + std::string extra_details; + + // Hacks to better print known event types. + if (type == NetLog::TYPE_URL_REQUEST_START || + type == NetLog::TYPE_SOCKET_STREAM_CONNECT) { + if (phase == NetLog::PHASE_BEGIN) { + extra_details = + StringPrintf("url: %s", extra_params->ToString().c_str()); + } else if (phase == NetLog::PHASE_END) { + int error_code = static_cast<NetLogIntegerParameter*>( + extra_params)->value(); + extra_details = StringPrintf("net error: %d (%s)", + error_code, + ErrorToString(error_code)); + } + } else if (type == NetLog::TYPE_SOCKET_POOL_CONNECT_JOB) { + extra_details = + StringPrintf("group: %s", extra_params->ToString().c_str()); + } else { + extra_details = extra_params->ToString(); + } + + int indentation = max_time_width + indentation_spaces + + kSpacesPerIndentation + 5; + + StringAppendF( + &result, + "\n%s%s", + PadStringLeft("", indentation).c_str(), + extra_details.c_str()); + } + if (i + 1 != entries_.size()) result += "\n"; } @@ -72,25 +122,23 @@ class FormatHelper { private: struct Entry { - explicit Entry(const NetLog::Entry* log_entry) + explicit Entry(const CapturingNetLog::Entry* log_entry) : log_entry(log_entry), indentation(0), block_index(-1) {} bool IsBeginEvent() const { - return log_entry->type == NetLog::Entry::TYPE_EVENT && - log_entry->event.phase == NetLog::PHASE_BEGIN; + return log_entry->phase == NetLog::PHASE_BEGIN; } bool IsEndEvent() const { - return log_entry->type == NetLog::Entry::TYPE_EVENT && - log_entry->event.phase == NetLog::PHASE_END; + return log_entry->phase == NetLog::PHASE_END; } - const NetLog::Entry* log_entry; + const CapturingNetLog::Entry* log_entry; size_t indentation; int block_index; // The index of the matching start / end of block. }; - void PopulateEntries(const std::vector<NetLog::Entry>& entries) { + void PopulateEntries(const std::vector<CapturingNetLog::Entry>& entries) { int current_indentation = 0; for (size_t i = 0; i < entries.size(); ++i) { @@ -127,7 +175,7 @@ class FormatHelper { // Find the matching start of block by scanning backwards. for (int i = entries_.size() - 1; i >= 0; --i) { if (entries_[i].IsBeginEvent() && - entries_[i].log_entry->event.type == entry.log_entry->event.type) { + entries_[i].log_entry->type == entry.log_entry->type) { return i; } } @@ -141,7 +189,7 @@ class FormatHelper { *max_time_width = *max_indentation = *max_type_width = *max_dt_width = 0; for (size_t i = 0; i < entries_.size(); ++i) { *max_time_width = std::max(*max_time_width, GetTimeString(i).size()); - if (entries_[i].log_entry->type == NetLog::Entry::TYPE_EVENT) + if (entries_[i].log_entry->phase != NetLog::PHASE_NONE) *max_type_width = std::max(*max_type_width, GetEntryString(i).size()); *max_indentation = std::max(*max_indentation, entries_[i].indentation); @@ -169,36 +217,19 @@ class FormatHelper { } std::string GetEntryString(size_t index) { - const NetLog::Entry* entry = entries_[index].log_entry; + const CapturingNetLog::Entry* entry = entries_[index].log_entry; std::string entry_str; - NetLog::EventPhase phase = NetLog::PHASE_NONE; - switch (entry->type) { - case NetLog::Entry::TYPE_EVENT: - entry_str = NetLog::EventTypeToString(entry->event.type); - phase = entry->event.phase; - - if (phase == NetLog::PHASE_BEGIN && - index + 1 < entries_.size() && - static_cast<size_t>(entries_[index + 1].block_index) == index) { - // If this starts an empty block, we will pretend it is a PHASE_NONE - // so we don't print the "+" prefix. - phase = NetLog::PHASE_NONE; - } - break; - case NetLog::Entry::TYPE_ERROR_CODE: - entry_str = StringPrintf("error code: %d (%s)", - entry->error_code, - ErrorToString(entry->error_code)); - break; - case NetLog::Entry::TYPE_STRING: - entry_str = StringPrintf("\"%s\"", entry->string.c_str()); - break; - case NetLog::Entry::TYPE_STRING_LITERAL: - entry_str = StringPrintf("\"%s\"", entry->literal); - break; - default: - NOTREACHED(); + NetLog::EventPhase phase = entry->phase; + + entry_str = NetLog::EventTypeToString(entry->type); + + if (phase == NetLog::PHASE_BEGIN && + index + 1 < entries_.size() && + static_cast<size_t>(entries_[index + 1].block_index) == index) { + // If this starts an empty block, we will pretend it is a PHASE_NONE + // so we don't print the "+" prefix. + phase = NetLog::PHASE_NONE; } switch (phase) { @@ -228,7 +259,7 @@ class FormatHelper { // static std::string NetLogUtil::PrettyPrintAsEventTree( - const std::vector<NetLog::Entry>& entries, + const std::vector<CapturingNetLog::Entry>& entries, size_t num_entries_truncated) { FormatHelper helper; return helper.ToString(entries, num_entries_truncated); diff --git a/net/base/net_log_util.h b/net/base/net_log_util.h index 716a941..7ca5e65 100644 --- a/net/base/net_log_util.h +++ b/net/base/net_log_util.h @@ -64,7 +64,8 @@ class NetLogUtil { // - Time units are given as milliseconds. // static std::string PrettyPrintAsEventTree( - const std::vector<NetLog::Entry>& entries, size_t num_entries_truncated); + const std::vector<CapturingNetLog::Entry>& entries, + size_t num_entries_truncated); private: DISALLOW_IMPLICIT_CONSTRUCTORS(NetLogUtil); diff --git a/net/base/net_log_util_unittest.cc b/net/base/net_log_util_unittest.cc index 713773d..9306fa9 100644 --- a/net/base/net_log_util_unittest.cc +++ b/net/base/net_log_util_unittest.cc @@ -10,34 +10,26 @@ namespace net { namespace { -NetLog::Entry MakeEventEntry(int t, - NetLog::EventType event_type, - NetLog::EventPhase event_phase) { - NetLog::Entry entry; - entry.type = NetLog::Entry::TYPE_EVENT; - entry.time = MakeTime(t); - entry.event = NetLog::Event(event_type, event_phase); - return entry; +CapturingNetLog::Entry MakeEventEntry(int t, + NetLog::EventType event_type, + NetLog::EventPhase event_phase) { + return CapturingNetLog::Entry(event_type, + MakeTime(t), + NetLog::Source(), + event_phase, + NULL); } -NetLog::Entry MakeStringEntry(int t, const std::string& string) { - NetLog::Entry entry; - entry.type = NetLog::Entry::TYPE_STRING; - entry.time = MakeTime(t); - entry.string = string; - return entry; -} - -NetLog::Entry MakeErrorCodeEntry(int t, int error_code) { - NetLog::Entry entry; - entry.type = NetLog::Entry::TYPE_ERROR_CODE; - entry.time = MakeTime(t); - entry.error_code = error_code; - return entry; +CapturingNetLog::Entry MakeStringEntry(int t, const std::string& string) { + return CapturingNetLog::Entry(NetLog::TYPE_TODO_STRING, + MakeTime(t), + NetLog::Source(), + NetLog::PHASE_NONE, + new NetLogStringParameter(string)); } TEST(NetLogUtilTest, Basic) { - std::vector<NetLog::Entry> log; + CapturingNetLog::EntryList log; log.push_back(MakeEventEntry(1, NetLog::TYPE_HOST_RESOLVER_IMPL, NetLog::PHASE_BEGIN)); @@ -63,13 +55,12 @@ TEST(NetLogUtilTest, Basic) { } TEST(NetLogUtilTest, Basic2) { - std::vector<NetLog::Entry> log; + CapturingNetLog::EntryList log; log.push_back(MakeEventEntry(1, NetLog::TYPE_HOST_RESOLVER_IMPL, NetLog::PHASE_BEGIN)); log.push_back(MakeStringEntry(12, "Sup foo")); - log.push_back(MakeErrorCodeEntry(12, ERR_UNEXPECTED)); log.push_back(MakeStringEntry(14, "Multiline\nString")); log.push_back(MakeEventEntry(131, NetLog::TYPE_HOST_RESOLVER_IMPL, @@ -78,7 +69,6 @@ TEST(NetLogUtilTest, Basic2) { EXPECT_EQ( "t= 1: +HOST_RESOLVER_IMPL [dt=130]\n" "t= 12: \"Sup foo\"\n" - "t= 12: error code: -9 (net::ERR_UNEXPECTED)\n" "t= 14: \"Multiline\n" "String\"\n" "t=131: -HOST_RESOLVER_IMPL", @@ -86,7 +76,7 @@ TEST(NetLogUtilTest, Basic2) { } TEST(NetLogUtilTest, UnmatchedOpen) { - std::vector<NetLog::Entry> log; + CapturingNetLog::EntryList log; log.push_back(MakeEventEntry(3, NetLog::TYPE_HOST_RESOLVER_IMPL, NetLog::PHASE_BEGIN)); @@ -117,7 +107,7 @@ TEST(NetLogUtilTest, UnmatchedOpen) { } TEST(NetLogUtilTest, DisplayOfTruncated) { - std::vector<NetLog::Entry> log; + CapturingNetLog::EntryList log; log.push_back(MakeEventEntry(0, NetLog::TYPE_TCP_CONNECT, diff --git a/net/proxy/proxy_service.cc b/net/proxy/proxy_service.cc index 4e7a342..668a659 100644 --- a/net/proxy/proxy_service.cc +++ b/net/proxy/proxy_service.cc @@ -464,9 +464,9 @@ int ProxyService::DidFinishResolvingProxy(ProxyInfo* result, } result->DeprioritizeBadProxies(proxy_retry_info_); } else { - net_log.AddStringLiteral( - "Got an error from proxy resolver, falling-back to DIRECT."); - net_log.AddErrorCode(result_code); + net_log.AddString(StringPrintf( + "Got an error from proxy resolver (%d), falling-back to DIRECT.", + result_code)); // Fall-back to direct when the proxy resolver fails. This corresponds // with a javascript runtime error in the PAC script. diff --git a/net/socket/client_socket_pool_base_unittest.cc b/net/socket/client_socket_pool_base_unittest.cc index 750a327..b0ddf55 100644 --- a/net/socket/client_socket_pool_base_unittest.cc +++ b/net/socket/client_socket_pool_base_unittest.cc @@ -835,7 +835,7 @@ TEST_F(ClientSocketPoolBaseTest, CloseIdleSocketAtSocketLimit) { InitHandle(&handle, "foo", kDefaultPriority, &callback, pool_, NULL)); - // But if we wait for it, the released idle sockets will be closed in + // But if we wait for it, the released idle sockets will be closed in // preference of the waiting request. EXPECT_EQ(OK, callback.WaitForResult()); @@ -1407,7 +1407,7 @@ TEST_F(ClientSocketPoolBaseTest, CleanupTimedOutIdleSockets) { EXPECT_EQ(OK, rv); EXPECT_TRUE(req.handle()->is_reused()); EXPECT_TRUE(LogContainsEntryWithType( - log.entries(), 1, NetLog::Entry::TYPE_STRING_LITERAL)); + log.entries(), 1, NetLog::TYPE_TODO_STRING_LITERAL)); } // Make sure that we process all pending requests even when we're stalling diff --git a/net/socket_stream/socket_stream.cc b/net/socket_stream/socket_stream.cc index bdd2894..8a78659 100644 --- a/net/socket_stream/socket_stream.cc +++ b/net/socket_stream/socket_stream.cc @@ -97,8 +97,7 @@ void SocketStream::set_context(URLRequestContext* context) { context->net_log(), NetLog::SOURCE_SOCKET_STREAM); - net_log_.BeginEventWithString(NetLog::TYPE_REQUEST_ALIVE, - url_.possibly_invalid_spec()); + net_log_.BeginEvent(NetLog::TYPE_REQUEST_ALIVE); } } @@ -121,7 +120,8 @@ void SocketStream::Connect() { // Open a connection asynchronously, so that delegate won't be called // back before returning Connect(). next_state_ = STATE_RESOLVE_PROXY; - net_log_.BeginEvent(NetLog::TYPE_SOCKET_STREAM_CONNECT); + net_log_.BeginEventWithString(NetLog::TYPE_SOCKET_STREAM_CONNECT, + url_.possibly_invalid_spec()); MessageLoop::current()->PostTask( FROM_HERE, NewRunnableMethod(this, &SocketStream::DoLoop, OK)); @@ -406,7 +406,7 @@ void SocketStream::DoLoop(int result) { // close the connection. if (state != STATE_READ_WRITE && result < ERR_IO_PENDING) { DCHECK_EQ(next_state_, STATE_CLOSE); - net_log_.EndEvent(NetLog::TYPE_SOCKET_STREAM_CONNECT); + net_log_.EndEventWithInteger(NetLog::TYPE_SOCKET_STREAM_CONNECT, result); } } while (result != ERR_IO_PENDING); } diff --git a/net/url_request/url_request.cc b/net/url_request/url_request.cc index 7ada4a9..348fb37 100644 --- a/net/url_request/url_request.cc +++ b/net/url_request/url_request.cc @@ -259,7 +259,8 @@ void URLRequest::StartJob(URLRequestJob* job) { DCHECK(!is_pending_); DCHECK(!job_); - net_log_.BeginEvent(net::NetLog::TYPE_URL_REQUEST_START); + net_log_.BeginEventWithString(net::NetLog::TYPE_URL_REQUEST_START, + original_url().possibly_invalid_spec()); job_ = job; job_->SetExtraRequestHeaders(extra_request_headers_); @@ -365,10 +366,12 @@ void URLRequest::ReceivedRedirect(const GURL& location, bool* defer_redirect) { } void URLRequest::ResponseStarted() { - if (!status_.is_success()) - net_log_.AddErrorCode(status_.os_error()); - - net_log_.EndEvent(net::NetLog::TYPE_URL_REQUEST_START); + if (!status_.is_success()) { + net_log_.EndEventWithInteger(net::NetLog::TYPE_URL_REQUEST_START, + status_.os_error()); + } else { + net_log_.EndEvent(net::NetLog::TYPE_URL_REQUEST_START); + } URLRequestJob* job = GetJobManager()->MaybeInterceptResponse(this); if (job) { @@ -515,9 +518,7 @@ void URLRequest::set_context(URLRequestContext* context) { if (context) { net_log_ = net::BoundNetLog::Make(context->net_log(), net::NetLog::SOURCE_URL_REQUEST); - - net_log_.BeginEventWithString(net::NetLog::TYPE_REQUEST_ALIVE, - original_url_.possibly_invalid_spec()); + net_log_.BeginEvent(net::NetLog::TYPE_REQUEST_ALIVE); } } } |