| OLD | NEW |
| 1 # A Crash Course in Debugging with about:net-internals | 1 # A Crash Course in Debugging with about:net-internals |
| 2 | 2 |
| 3 This document is intended to help get people started debugging network errors | 3 This document is intended to help get people started debugging network errors |
| 4 with about:net-internals, with some commonly useful tips and tricks. This | 4 with about:net-internals, with some commonly useful tips and tricks. This |
| 5 document is aimed more at how to get started using some of its features to | 5 document is aimed more at how to get started using some of its features to |
| 6 investigate bug reports, rather than as a feature overview. | 6 investigate bug reports, rather than as a feature overview. |
| 7 | 7 |
| 8 It would probably be useful to read | 8 It would probably be useful to read |
| 9 [life-of-a-url-request.md](life-of-a-url-request.md) before this document. | 9 [life-of-a-url-request.md](life-of-a-url-request.md) before this document. |
| 10 | 10 |
| 11 # What Data Net-Internals Contains | 11 # What Data Net-Internals Contains |
| 12 | 12 |
| 13 about:net-internals provides a view of browser activity from net/'s perspective. | 13 about:net-internals provides a view of browser activity from net/'s perspective. |
| 14 For this reason, it lacks knowledge of tabs, navigation, frames, resource types, | 14 For this reason, it lacks knowledge of tabs, navigation, frames, resource types, |
| 15 etc. | 15 etc. |
| 16 | 16 |
| 17 The top level network stack object is the URLRequestContext. The Events View | 17 The leftmost column presents a list of views. Most debugging is done with the |
| 18 Events view, which will be all this document covers. |
| 19 |
| 20 The top level network stack object is the URLRequestContext. The Events view |
| 18 has information for all Chrome URLRequestContexts that are hooked up to the | 21 has information for all Chrome URLRequestContexts that are hooked up to the |
| 19 single, global, ChromeNetLog object. This includes both incognito and non- | 22 single, global, ChromeNetLog object. This includes both incognito and |
| 20 incognito profiles, among other things. The Events view only shows events for | 23 non-incognito profiles, among other things. The Events view only shows events |
| 21 the period that net-internals was open and running, and is incrementally updated | 24 for the period that net-internals was open and running, and is incrementally |
| 22 as events occur. The code attempts to add a top level event for URLRequests | 25 updated as events occur. The code attempts to add a top level event for |
| 23 that were active when the tab was opened, to help debug hung requests, but | 26 URLRequests that were active when the about:net-internals tab was opened, to |
| 24 that's best-effort only, and only includes requests for the current profile and | 27 help debug hung requests, but that's best-effort only, and only includes |
| 25 the system URLRequestContext. | 28 requests for the current profile and the system URLRequestContext. |
| 26 | 29 |
| 27 The other views are all snapshots of the current state of the main | 30 The other views are all snapshots of the current state of the main |
| 28 URLRequestContext's components, and are updated on a 5 second timer. These will | 31 URLRequestContext's components, and are updated on a 5 second timer. These will |
| 29 show objects that were created before about:net-internals was opened. Most | 32 show objects that were created before about:net-internals was opened. |
| 30 debugging is done with the Events view (which will be all this document | |
| 31 covers), but it's good to be aware of this distinction. | |
| 32 | 33 |
| 33 # Events vs Sources | 34 # Events vs Sources |
| 34 | 35 |
| 35 The Event View shows events logged by the NetLog. The NetLog model is that | 36 The Events view shows events logged by the NetLog. The NetLog model is that |
| 36 long-lived network stack objects, called sources, emit events over their | 37 long-lived network stack objects, called sources, emit events over their |
| 37 lifetime. When looking at the code, a "NetLogWithSource" object contains a sour
ce | 38 lifetime. A NetLogWithSource object contains a source ID, a NetLogSourceType, |
| 38 ID, and a pointer to the NetLog the source emits events to. Some events have a | 39 and a pointer to the NetLog the source emits events to. |
| 39 beginning and end point (during which other subevents may occur), and some only | 40 |
| 40 occur at a single point in time. Generally only one event can be occuring for a | 41 The Events view has a list of sources in a column adjacent to the list of views. |
| 41 source at a time. If there can be multiple events doing completely independent | 42 Sources that include an event with a net_error parameter with negative value |
| 42 thing, the code often uses new sources to represent the parallelism. | 43 (that is, some kind of ERR_) are shown with red background. Sources whose |
| 44 opening event has not ended yet are shown with white background. Other events |
| 45 have green background. The search queries corresponding to the first two kinds |
| 46 are `is:error` and `is:active`. |
| 47 |
| 48 When one or more sources are selected, corresponding events show up in another |
| 49 column to the right, sorted by source, and by time within each source. There |
| 50 are two time values: t is measured from some reference point common to all |
| 51 sources, and st is measured from the first event for each source. Time is |
| 52 displayed in milliseconds. |
| 53 |
| 54 Since the network stack is asynchronous, events from different sources will |
| 55 often be interlaced in time, but Events view does not feature showing events fro
m |
| 56 different sources ordered by time. Large time gaps in the event list of a |
| 57 single source usually mean that time is spent in the context of another source. |
| 58 |
| 59 Some events come in pairs: a beginning and end event, between which other events |
| 60 may occur. They are shown with + and - prefixes, respectively. The begin event |
| 61 has a dt value which shows the duration. If the end event was captured, then |
| 62 duration is calculated as the time difference between the begin and the end |
| 63 events. Otherwise the time elapsed from the begin event until capturing |
| 64 was stopped is displayed (a lower bound for actual duration), followed by a + |
| 65 sign (for example, "dt=120+"). |
| 66 |
| 67 If there are no other events in between the begin and end, and the end event has |
| 68 no parameters, then they are collapsed in a single line without a sign prefix. |
| 69 |
| 70 Some other events only occur at a single point in time, and will not have either |
| 71 a sign prefix, or a dt duration value. |
| 72 |
| 73 Generally only one event can be occuring for a source at a time. If there can |
| 74 be multiple events doing completely independent things, the code often uses new |
| 75 sources to represent the parallelism. |
| 76 |
| 77 Most, but not all events correspond to a source. Exceptions are global events, |
| 78 which have no source, and show up as individual entries in the source list. |
| 79 Examples of global events include NETWORK_CHANGED, DNS_CONFIG_CHANGED, and |
| 80 PROXY_CONFIG_CHANGED. |
| 81 |
| 82 # Common source types |
| 43 | 83 |
| 44 "Sources" correspond to certain net objects, however, multiple layers of net/ | 84 "Sources" correspond to certain net objects, however, multiple layers of net/ |
| 45 will often log to a single source. Here are the main source types and what they | 85 will often log to a single source. Here are the main source types and what they |
| 46 include (Excluding HTTP2 [SPDY]/QUIC): | 86 include (excluding HTTP2 [SPDY]/QUIC): |
| 47 | 87 |
| 48 * URL_REQUEST: This corresponds to the URLRequest object. It includes events | 88 * URL_REQUEST: This corresponds to the URLRequest object. It includes events |
| 49 from all the URLRequestJobs, HttpCache::Transactions, NetworkTransactions, | 89 from all the URLRequestJobs, HttpCache::Transactions, NetworkTransactions, |
| 50 HttpStreamFactoryImpl::Requests, HttpStream implementations, and | 90 HttpStreamFactoryImpl::Requests, HttpStream implementations, and |
| 51 HttpStreamParsers used to service a response. If the URL_REQUEST follows HTTP | 91 HttpStreamParsers used to service a response. If the URL_REQUEST follows HTTP |
| 52 redirects, it will include each redirect. This is a lot of stuff, but generally | 92 redirects, it will include each redirect. This is a lot of stuff, but generally |
| 53 only object is doing work at a time. This event source includes the full URL | 93 only one object is doing work at a time. This event source includes the full |
| 54 and generally includes the request / response headers (Except when the cache | 94 URL and generally includes the request / response headers (except when the cache |
| 55 handles the response). | 95 handles the response). |
| 56 | 96 |
| 57 * HTTP_STREAM_JOB: This corresponds to HttpStreamFactoryImpl::Job (Note that | 97 * HTTP_STREAM_JOB: This corresponds to HttpStreamFactoryImpl::Job (note that |
| 58 one Request can have multiple Jobs). It also includes its proxy and DNS | 98 one Request can have multiple Jobs). It also includes its proxy and DNS |
| 59 lookups. HTTP_STREAM_JOB log events are separate from URL_REQUEST because | 99 lookups. HTTP_STREAM_JOB log events are separate from URL_REQUEST because two |
| 60 two stream jobs may be created and races against each other, in some cases - | 100 stream jobs may be created and races against each other, in some cases -- one |
| 61 one for one for QUIC, and one for HTTP. One of the final events of this source | 101 for QUIC, and one for HTTP. |
| 62 indicates how an HttpStream was created (Reusing an existing SOCKET / | 102 |
| 63 HTTP2_SESSION / QUIC_SESSION, or creating a new one). | 103 One of the final events of this source, before the |
| 104 HTTP_STREAM_JOB_BOUND_TO_REQUEST event, indicates how an HttpStream was |
| 105 created: |
| 106 |
| 107 + A SOCKET_POOL_BOUND_TO_CONNECT_JOB event means that a new TCP socket was |
| 108 created, whereas a SOCKET_POOL_REUSED_AN_EXISTING_SOCKET event indicates tha
t |
| 109 an existing TCP socket was reused for a non-HTTP/2 request. |
| 110 |
| 111 + An HTTP2_SESSION_POOL_IMPORTED_SESSION_FROM_SOCKET event indicates that a |
| 112 new HTTP/2 session was opened by this Job. |
| 113 |
| 114 + An HTTP2_SESSION_POOL_FOUND_EXISTING_SESSION event indicates that the requ
est |
| 115 was served on a preexisting HTTP/2 session. |
| 116 |
| 117 + An HTTP2_SESSION_POOL_FOUND_EXISTING_SESSION_FROM_IP_POOL event means that |
| 118 the request was pooled to a preexisting HTTP/2 session which had a different |
| 119 SpdySessionKey, but DNS resolution resulted in the same IP, and the |
| 120 certificate matches. |
| 121 |
| 122 + There are currently no events logged for opening new QUIC sessions or |
| 123 reusing existing ones. |
| 64 | 124 |
| 65 * \*_CONNECT_JOB: This corresponds to the ConnectJob subclasses that each socke
t | 125 * \*_CONNECT_JOB: This corresponds to the ConnectJob subclasses that each socke
t |
| 66 pool uses. A successful CONNECT_JOB return a SOCKET. The events here vary a | 126 pool uses. A successful CONNECT_JOB returns a SOCKET. The events here vary a |
| 67 lot by job type. Their main event is generally either to create a socket, or | 127 lot by job type. Their main event is generally either to create a socket, or |
| 68 request a socket from another socket pool (Which creates another CONNECT_JOB) | 128 request a socket from another socket pool (which creates another CONNECT_JOB) |
| 69 and then do some extra work on top of that - like establish an SSL connection on | 129 and then do some extra work on top of that -- like establish an SSL connection o
n |
| 70 top of a TCP connection. | 130 top of a TCP connection. |
| 71 | 131 |
| 72 * SOCKET: These correspond to TCPSockets, but may also have other classes | 132 * SOCKET: These correspond to TCPSockets, but may also have other classes |
| 73 layered on top of them (Like an SSLClientSocket). This is a bit different from | 133 layered on top of them (like an SSLClientSocket). This is a bit different from |
| 74 the other classes, where the name corresponds to the topmost class, instead of | 134 the other classes, where the name corresponds to the topmost class, instead of |
| 75 the bottommost one. This is largely an artifact of the fact the socket is | 135 the bottommost one. This is largely an artifact of the fact the socket is |
| 76 created first, and then SSL (Or a proxy connection) is layered on top of it. | 136 created first, and then SSL (or a proxy connection) is layered on top of it. |
| 77 SOCKETs may be reused between multiple requests, and a request may end up | 137 SOCKETs may be reused between multiple requests, and a request may end up |
| 78 getting a socket created for another request. | 138 getting a socket created for another request. |
| 79 | 139 |
| 80 * HOST_RESOLVER_IMPL_JOB: These correspond to HostResolverImpl::Job. The | 140 * HOST_RESOLVER_IMPL_JOB: These correspond to HostResolverImpl::Job. They |
| 81 include information about how long the lookup was queued, each DNS request that | 141 include information about how long the lookup was queued, each DNS request that |
| 82 was attempted (With the platform or built-in resolver) and all the other sources | 142 was attempted (with the platform or built-in resolver) and all the other sources |
| 83 that are waiting on the job. | 143 that are waiting on the job. |
| 84 | 144 |
| 85 When one source depends on another, the code generally logs an event with | 145 When one source depends on another, the code generally logs an event at both |
| 86 "source_dependency" value to both sources, which lets you jump between the two | 146 sources with a `source_dependency` value pointing to the other source. These |
| 87 related events. | 147 are clickable in the UI, adding the referred source to the list of selected |
| 148 sources. |
| 88 | 149 |
| 89 # Debugging | 150 # Debugging |
| 90 | 151 |
| 91 When you receive a report from the user, the first thing you'll generally want | 152 When you receive a report from the user, the first thing you'll generally want |
| 92 to do find the URL_REQUEST[s] that are misbehaving. If the user gives an ERR_* | 153 to do find the URL_REQUEST[s] that are misbehaving. If the user gives an ERR_* |
| 93 code or the exact URL of the resource that won't load, you can just search for | 154 code or the exact URL of the resource that won't load, you can just search for |
| 94 it. If it's an upload, you can search for "post", or if it's a redirect issue, | 155 it. If it's an upload, you can search for "post", or if it's a redirect issue, |
| 95 you can search for "redirect". However, you often won't have much information | 156 you can search for "redirect". However, you often won't have much information |
| 96 about the actual problem. There are two filters in net-internals that can help | 157 about the actual problem. There are two filters in net-internals that can help |
| 97 in a lot of cases: | 158 in a lot of cases: |
| 98 | 159 |
| 99 * "type:URL_REQUEST is:error" will restrict the list to URL_REQUEST object with | 160 * "type:URL_REQUEST is:error" will restrict the source list to URL_REQUEST |
| 100 an error of some sort (red background). Cache errors are often non-fatal, so | 161 objects with an error of some sort. Cache errors are often non-fatal, so you |
| 101 you should generally ignore those, and look for a more interesting one. | 162 should generally ignore those, and look for a more interesting one. |
| 102 | 163 |
| 103 * "type:URL_REQUEST sort:duration" will show the longest-lived requests first. | 164 * "type:URL_REQUEST sort:duration" will show the longest-lived requests first. |
| 104 This is often useful in finding hung or slow requests. | 165 This is often useful in finding hung or slow requests. |
| 105 | 166 |
| 106 For a list of other filter commands, you can mouse over the question mark on | 167 For a list of other filter commands, you can mouse over the question mark on |
| 107 about:net-internals. | 168 about:net-internals. |
| 108 | 169 |
| 109 Once you locate the problematic request, the next is to figure out where the | 170 Once you locate the problematic request, the next is to figure out where the |
| 110 problem is - it's often one of the last events, though it could also be related | 171 problem is -- it's often one of the last events, though it could also be related |
| 111 to response or request headers. You can use "source_dependency" links to drill | 172 to response or request headers. You can use `source_dependency` links to |
| 112 down into other related sources, or up from layers below URL_REQUEST. | 173 navigate between related sources. You can use the name of an event to search |
| 113 | 174 for the code responsible for that event, and try to deduce what went wrong |
| 114 You can use the name of an event to search for the code responsible for that | 175 before/after a particular event. |
| 115 event, and try to deduce what went wrong before/after a particular event. Note | |
| 116 that the event names used in net-internals are not the entire string names, so | |
| 117 you should not do an entire string match. | |
| 118 | 176 |
| 119 Some things to look for while debugging: | 177 Some things to look for while debugging: |
| 120 | 178 |
| 121 * CANCELLED events almost always come from outside the network stack. | 179 * CANCELLED events almost always come from outside the network stack. |
| 122 | 180 |
| 123 * Changing networks and entering / exiting suspend mode can have all sorts of | 181 * Changing networks and entering / exiting suspend mode can have all sorts of |
| 124 fun and exciting effects on underway network activity. Network changes log a | 182 fun and exciting effects on underway network activity. Network changes log a |
| 125 top level NETWORK_CHANGED event with no source - the event itself is treated as | 183 top level NETWORK_CHANGED event. Suspend events are currently not logged. |
| 126 its own source. Suspend events are currently not logged. | |
| 127 | 184 |
| 128 * URL_REQUEST_DELEGATE / DELEGATE_INFO events mean a URL_REQUEST is blocked on a | 185 * URL_REQUEST_DELEGATE / DELEGATE_INFO events mean a URL_REQUEST is blocked on a |
| 129 URLRequest::Delegate or the NetworkDelegate, which are implemented outside the | 186 URLRequest::Delegate or the NetworkDelegate, which are implemented outside the |
| 130 network stack. A request will sometimes be CANCELED here for reasons known only | 187 network stack. A request will sometimes be CANCELED here for reasons known only |
| 131 to the delegate. Or the delegate may cause a hang. In general, to debug issues | 188 to the delegate. Or the delegate may cause a hang. In general, to debug issues |
| 132 related to delegates, one needs to figure out which method of which object is | 189 related to delegates, one needs to figure out which method of which object is |
| 133 causing the problem. The object may be the a NetworkDelegate, a | 190 causing the problem. The object may be the a NetworkDelegate, a |
| 134 ResourceThrottle, a ResourceHandler, the ResourceLoader itself, or the | 191 ResourceThrottle, a ResourceHandler, the ResourceLoader itself, or the |
| 135 ResourceDispatcherHost. | 192 ResourceDispatcherHost. |
| 136 | 193 |
| 137 * Sockets are often reused between requests. If a request is on a stale | 194 * Sockets are often reused between requests. If a request is on a stale |
| 138 (reused) socket, what was the previous request that used the socket, how long | 195 (reused) socket, what was the previous request that used the socket, how long |
| 139 ago was it made? | 196 ago was it made? (Look at SOCKET_IN_USE events, and the HTTP_STREAM_JOBS they |
| 197 point to via the `source_dependency` value.) |
| 140 | 198 |
| 141 * SSL negotation is a process fraught with peril, particularly with broken | 199 * SSL negotation is a process fraught with peril, particularly with broken |
| 142 proxies. These will generally stall or fail in the SSL_CONNECT phase at the | 200 proxies. These will generally stall or fail in the SSL_CONNECT phase at the |
| 143 SOCKET layer. | 201 SOCKET layer. |
| 144 | 202 |
| 145 * Range requests have magic to handle them at the cache layer, and are often | 203 * Range requests have magic to handle them at the cache layer, and are often |
| 146 issued by the media and PDF code. | 204 issued by the media and PDF code. |
| 147 | 205 |
| 148 * Late binding: HTTP_STREAM_JOBs are not associated with any CONNECT_JOB until | 206 * Late binding: HTTP_STREAM_JOBs are not associated with any CONNECT_JOB until |
| 149 a CONNECT_JOB actually connects. This is so the highest priority pending job | 207 a CONNECT_JOB actually connects. This is so the highest priority pending |
| 150 gets the first available socket (Which may be a new socket, or an old one that's | 208 HTTP_STREAM_JOB gets the first available socket (which may be a new socket, or |
| 151 freed up). For this reason, it can be a little tricky to relate hung | 209 an old one that's freed up). For this reason, it can be a little tricky to |
| 152 HTTP_STREAM_JOBs to CONNECT_JOBs. | 210 relate hung HTTP_STREAM_JOBs to CONNECT_JOBs. |
| 153 | 211 |
| 154 * Each CONNECT_JOB belongs to a "group", which has a limit of 6 connections. If | 212 * Each CONNECT_JOB belongs to a "group", which has a limit of 6 connections. If |
| 155 all CONNECT_JOBs beling to a group (The CONNECT_JOB's description field) are | 213 all CONNECT_JOBs belonging to a group (the CONNECT_JOB's description field) are |
| 156 stalled waiting on an available socket, the group probably has 6 sockets that | 214 stalled waiting on an available socket, the group probably has 6 sockets that |
| 157 that are hung - either hung trying to connect, or used by stalled requests and | 215 that are hung -- either hung trying to connect, or used by stalled requests and |
| 158 thus outside the socket pool's control. | 216 thus outside the socket pool's control. |
| 159 | 217 |
| 160 * There's a limit on number of DNS resolutions that can be started at once. If | 218 * There's a limit on number of DNS resolutions that can be started at once. If |
| 161 everything is stalled while resolving DNS addresses, you've probably hit this | 219 everything is stalled while resolving DNS addresses, you've probably hit this |
| 162 limit, and the DNS lookups are also misbehaving in some fashion. | 220 limit, and the DNS lookups are also misbehaving in some fashion. |
| 163 | 221 |
| 164 # Miscellany | 222 # Miscellany |
| 165 | 223 |
| 166 These are just miscellaneous things you may notice when looking through the | 224 These are just miscellaneous things you may notice when looking through the |
| 167 logs. | 225 logs. |
| 168 | 226 |
| 169 * URLRequests that look to start twice for no obvious reason. These are | 227 * URLRequests that look to start twice for no obvious reason. These are |
| 170 typically main frame requests, and the first request is AppCache. Can just | 228 typically main frame requests, and the first request is AppCache. Can just |
| 171 ignore it and move on with your life. | 229 ignore it and move on with your life. |
| 172 | 230 |
| 173 * Some HTTP requests are not handled by URLRequestHttpJobs. These include | 231 * Some HTTP requests are not handled by URLRequestHttpJobs. These include |
| 174 things like HSTS redirects (URLRequestRedirectJob), AppCache, ServiceWorker, | 232 things like HSTS redirects (URLRequestRedirectJob), AppCache, ServiceWorker, |
| 175 etc. These generally don't log as much information, so it can be tricky to | 233 etc. These generally don't log as much information, so it can be tricky to |
| 176 figure out what's going on with these. | 234 figure out what's going on with these. |
| 177 | 235 |
| 178 * Non-HTTP requests also appear in the log, and also generally don't log much | 236 * Non-HTTP requests also appear in the log, and also generally don't log much |
| 179 (blob URLs, chrome URLs, etc). | 237 (blob URLs, chrome URLs, etc). |
| 180 | 238 |
| 181 * Preconnects create a "HTTP_STREAM_JOB" event that may create multiple | 239 * Preconnects create a "HTTP_STREAM_JOB" event that may create multiple |
| 182 CONNECT_JOBs (or none) and is then destroyed. These can be identified by the | 240 CONNECT_JOBs (or none) and is then destroyed. These can be identified by the |
| 183 "SOCKET_POOL_CONNECTING_N_SOCKETS" events. | 241 "SOCKET_POOL_CONNECTING_N_SOCKETS" events. |
| OLD | NEW |