[DO NOT SUBMIT, PATCH on commit 7fa349e632a44c152b05ca6a66ade5f2e5b3f139]

[DO NOT SUBMIT, PATCH on commit 7fa349e632a44c152b05ca6a66ade5f2e5b3f139]

Add more Quic related NetLogs for debugging crbug.com/700617.
1. More granular states in HTTP_STREAM_JOB:
if it's a alt job, whether it uses exisiting active session,
                        or it binds to active jobs
                        or it creates new QuicStreamFactory::Job
2. More logging when alt job is deleted.
3. Seperate QUIC_STREAM_FACTORY_JOB net_log, with granular states logging.
4. QUIC_STREAM_FACTORY_JOB and HTTP_STREAM_JOB(alt_job) is now linked.

BUG=700617

[Zhongyi Shi, 2017-03-16 03:21:50]

zhongyi@chromium.org changed reviewers:
+ rch@chromium.org

[Zhongyi Shi, 2017-03-16 03:21:51]

Added some net-logs to the code so that when we repro, will have more info to
investigate. 

Ryan, ptal! Let me know if there's anything else we need to add.

An sample net log is at https://goo.gl/9AM8Mv.

[Ryan Hamilton, 2017-03-16 03:40:15]

looks good to me. hopefully this gets us what we need!

[eroman, 2017-03-16 04:32:07]

eroman@chromium.org changed reviewers:
+ eroman@chromium.org

[eroman, 2017-03-16 04:32:09]

I had started doing a drive-by review and leaving comments, before realizing
this was not actually intended to be landed :)

Figured I may as well publish my comments, but obviously no real need to address
them if this is just a change to compile an instrumented build.

One pattern that comes to mind if you want to throw in tons of "maybe this is
interesting" points could be to litter the code with something like:

   NET_LOG_REACHED(net_log_);

Which is easy to copy-paste, and then have the macro emit an event whose
parameters object contains the name of the function, filename, and line number.
Quick to add more trace points, but reading the resulting log will require a bit
more correlation to the source code.

#define NET_LOG_REACHED(net_log) AddNetLogReachedEvent(net_log, __func__,
__FILE__, __LINE__)

void AddNetLogReachedEvent(const NetLogWithSource& net_log, const char*
function, const char* filename, int line) {
  net_log_.AddEvent(
      NetLogEventType::NET_LOG_REACHED_FOR_DEBUGGING,
      LocationParamsCallback(function, filename, line));
}

https://codereview.chromium.org/2754003002/diff/1/net/http/http_stream_factor...
File net/http/http_stream_factory_impl_job.cc (right):

https://codereview.chromium.org/2754003002/diff/1/net/http/http_stream_factor...
net/http/http_stream_factory_impl_job.cc:129:
dict->SetString("delay_in_macroseconds", base::Int64ToString(delay));
microseconds.

Also on a side-note, I expect it will be easier to read the logs if these are in
milliseconds.

https://codereview.chromium.org/2754003002/diff/1/net/http/http_stream_factor...
File net/http/http_stream_factory_impl_job_controller.cc (right):

https://codereview.chromium.org/2754003002/diff/1/net/http/http_stream_factor...
net/http/http_stream_factory_impl_job_controller.cc:78:
NetLogEventType::ALT_JOB_DELETED_ON_DESTRUCT_JOB_CONTROLLER);
Instead of having multiple different event types (ALT_JOB_DELETED_ON_XXXX), how
about using a single event?

Here is the pattern I would suggest:

void ResetAlternativeJob(const char* function_name) {
  net_log_.AddEvent(
      NetLogEventType::JOB_CONTROLLER_RESET_ALT_JOB,
      NetLog::StringCallback("location", function_name));

  alternative_job_.reset();
}

Then replace each callsite of alternative_job_.reset() with:

    ResetAlternativeJob(__func__);

(if you prefer, can use __FILE__ and __LINE__, but __func__ is more stable IMO).

https://codereview.chromium.org/2754003002/diff/1/net/http/http_stream_factor...
net/http/http_stream_factory_impl_job_controller.cc:296:
net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_ON_STREAM_FAILED);
The begin/end measured by this event is entire synchronous. Just to confirm,
this is because you are interested in seeing if anything interesting happens
while within this stack frame?

[Optional] Instead of preceding each "return" with an EndEvent can use RAII. I
would be fine with throwing something like this into src/net/log:

class ScopedNetLogEndEvent {
 public:
  ScopedNetLogEndEvent(const NetLogWithSource& net_log, NetLogEventType event)
    : net_log_(net_log), event_(event) {}

  ~ScopedNetLogEndEvent() {
    net_log_.EndEvent(event);
  }

private:
  NetLogWithSource net_log_;
  NetLogEventType event;
};

https://codereview.chromium.org/2754003002/diff/1/net/http/http_stream_factor...
net/http/http_stream_factory_impl_job_controller.cc:681: delay,
base::TimeDelta::FromMilliseconds(kMaxDelayTimeForMainJobSecs));
Why this change? The variable is named "ForSecs".

https://codereview.chromium.org/2754003002/diff/1/net/log/net_log_event_type_...
File net/log/net_log_event_type_list.h (right):

https://codereview.chromium.org/2754003002/diff/1/net/log/net_log_event_type_...
net/log/net_log_event_type_list.h:1120: //            TEMP Net LOG for debugging
crbug.com/700617
[optional]: If you plan on deleting these later, you may consider giving them a
common prefix like BUG700617_XXX.

https://codereview.chromium.org/2754003002/diff/1/net/log/net_log_event_type_...
net/log/net_log_event_type_list.h:1138: //      "delay_in_macroseconds": <Number
of milliseconds alt job want to set
macro --> micro

https://codereview.chromium.org/2754003002/diff/1/net/log/net_log_event_type_...
net/log/net_log_event_type_list.h:1236:
EVENT_TYPE(QUIC_STREAM_FACTORY_JOB_COMPLTE_FROM_FACTORY)
typo: COMPLETE

https://codereview.chromium.org/2754003002/diff/1/net/log/net_log_event_type_...
net/log/net_log_event_type_list.h:1239: // 1. it's finishes with NOT OK, but
there are other jobs.
it's --> it

https://codereview.chromium.org/2754003002/diff/1/net/log/net_log_event_type_...
net/log/net_log_event_type_list.h:1254: // Location of alt job deletaion.
deletion

https://codereview.chromium.org/2754003002/diff/1/net/quic/chromium/quic_stre...
File net/quic/chromium/quic_stream_factory.cc (right):

https://codereview.chromium.org/2754003002/diff/1/net/quic/chromium/quic_stre...
net/quic/chromium/quic_stream_factory.cc:1085:
NetLog::Int64Callback("job_count", job_count));
nit: I don't think an int64 is necessary here.

https://codereview.chromium.org/2754003002/diff/1/net/quic/chromium/quic_stre...
net/quic/chromium/quic_stream_factory.cc:1150:
NetLog::Int64Callback("active_job_count", job_count));
same

[Zhongyi Shi, 2017-03-16 18:02:30]

Thanks Eric for those suggestions. Since this is only for instrumented build and
given the timeline to repro is long, I will leave them behind to expedite the
repro. But I will take them in a following CL which adds more net logs and is
targeted to land in Chrome.

[erikchen, 2017-03-16 18:13:30]

On 2017/03/16 18:02:30, Zhongyi Shi wrote:
> Thanks Eric for those suggestions. Since this is only for instrumented build
and
> given the timeline to repro is long, I will leave them behind to expedite the
> repro. But I will take them in a following CL which adds more net logs and is
> targeted to land in Chrome.

patch set 1 crashes on launch:
"""
* thread #21: tid = 0x606db0, 0x0000000103324906 Google Chrome
Framework`net::NetLogWithSource::EndEvent(net::NetLogEventType) const [inlined]
net::NetLogWithSource::CrashIfInvalid(this=0x00000064b19010b8) const + 1 at
net_log_with_source.cc:142, name = 'Chrome_IOThread', stop reason =
EXC_BREAKPOINT (code=EXC_I386_BPT, subcode=0x0)
    frame #0: 0x0000000103324906 Google Chrome
Framework`net::NetLogWithSource::EndEvent(net::NetLogEventType) const [inlined]
net::NetLogWithSource::CrashIfInvalid(this=0x00000064b19010b8) const + 1 at
net_log_with_source.cc:142 [opt]
    frame #1: 0x0000000103324905 Google Chrome
Framework`net::NetLogWithSource::EndEvent(net::NetLogEventType) const [inlined]
net::NetLogWithSource::AddEntry(this=0x00000064b19010b8, phase=END) const at
net_log_with_source.cc:46 [opt]
  * frame #2: 0x0000000103324905 Google Chrome
Framework`net::NetLogWithSource::EndEvent(this=0x00000064b19010b8,
type=HTTP_STREAM_JOB_ON_STREAM_FAILED) const + 85 at net_log_with_source.cc:85
[opt]
    frame #3: 0x000000010341578f Google Chrome
Framework`net::HttpStreamFactoryImpl::JobController::OnStreamFailed(this=0x00000064b1900ff0,
job=<unavailable>, status=-105, used_ssl_config=<unavailable>) + 543 at
http_stream_factory_impl_job_controller.cc:0 [opt]
    frame #4: 0x0000000103214710 Google Chrome
Framework`base::debug::TaskAnnotator::RunTask(char const*, base::PendingTask*)
[inlined] base::internal::RunMixin<base::Callback<void (),
(base::internal::CopyMode)0, (base::internal::RepeatMode)0> >::Run() && + 22 at
callback.h:68 [opt]
    frame #5: 0x00000001032146fa Google Chrome
Framework`base::debug::TaskAnnotator::RunTask(this=<unavailable>,
queue_function="MessageLoop::PostTask", pending_task=0x000070000a095be8) + 266
at task_annotator.cc:59 [opt]
    frame #6: 0x000000010323a1cb Google Chrome
Framework`base::MessageLoop::RunTask(this=0x0000000108a27ca0,
pending_task=0x000070000a095be8) + 523 at message_loop.cc:423 [opt]
    frame #7: 0x000000010323a51c Google Chrome
Framework`base::MessageLoop::DeferOrRunPendingTask(this=0x0000000108a27ca0,
pending_task=PendingTask @ 0x000070000a095be8) + 44 at message_loop.cc:434 [opt]
    frame #8: 0x000000010323a8e3 Google Chrome
Framework`base::MessageLoop::DoWork(this=0x0000000108a27ca0) + 387 at
message_loop.cc:527 [opt]
    frame #9: 0x000000010323d095 Google Chrome
Framework`base::MessagePumpLibevent::Run(this=0x0000000100500fc0,
delegate=0x0000000108a27ca0) + 245 at message_pump_libevent.cc:219 [opt]
    frame #10: 0x000000010325c133 Google Chrome
Framework`base::RunLoop::Run(this=0x000070000a095e60) + 115 at run_loop.cc:37
[opt]
    frame #11: 0x0000000101cbe0f4 Google Chrome
Framework`content::BrowserThreadImpl::IOThreadRun(this=<unavailable>,
run_loop=<unavailable>) + 20 at browser_thread_impl.cc:277 [opt]
    frame #12: 0x0000000101cbe1bc Google Chrome
Framework`content::BrowserThreadImpl::Run(this=0x0000000108a27ad0,
run_loop=0x000070000a095e60) + 172 at browser_thread_impl.cc:312 [opt]
    frame #13: 0x000000010328ace9 Google Chrome
Framework`base::Thread::ThreadMain(this=0x0000000108a27ad0) + 393 at
thread.cc:333 [opt]
    frame #14: 0x0000000103285dd7 Google Chrome Framework`base::(anonymous
namespace)::ThreadFunc(params=<unavailable>) + 87 at platform_thread_posix.cc:71
[opt]
    frame #15: 0x00007fffc35e5aab libsystem_pthread.dylib`_pthread_body + 180
    frame #16: 0x00007fffc35e59f7 libsystem_pthread.dylib`_pthread_start + 286
    frame #17: 0x00007fffc35e51fd libsystem_pthread.dylib`thread_start + 13
(lldb) frame select 0
frame #0: 0x0000000103324906 Google Chrome
Framework`net::NetLogWithSource::EndEvent(net::NetLogEventType) const [inlined]
net::NetLogWithSource::CrashIfInvalid(this=0x00000064b19010b8) const + 1 at
net_log_with_source.cc:142 [opt]
   139 	    return;
   140 	
   141 	  base::debug::Alias(&liveness);
-> 142 	  CHECK_EQ(ALIVE, liveness);
   143 	}
   144 	
   145 	}  // namespace net
"""

[erikchen, 2017-03-16 18:28:24]

Partial disassembly of frame 3 shows:
"""
    0x10341575a <+490>: mov    rdx, r15
    0x10341575d <+493>: call   0x103324790               ;
net::NetLogWithSource::AddEvent at net_log_with_source.cc:70
    0x103415762 <+498>: mov    rdi, r15
    0x103415765 <+501>: call   0x10320f6d0               ;
base::internal::CallbackBase<(base::internal::CopyMode)0>::~CallbackBase at
callback_internal.cc:79
    0x10341576a <+506>: mov    rdi, rbx
    0x10341576d <+509>: call   0x103416e60               ;
net::HttpStreamFactoryImpl::JobController::OrphanUnboundJob at
http_stream_factory_impl_job_controller.cc:799
    0x103415772 <+514>: mov    rdi, qword ptr [rbx + 0x28]
    0x103415776 <+518>: mov    esi, r12d
    0x103415779 <+521>: mov    rdx, qword ptr [rbp - 0x38]
    0x10341577d <+525>: call   0x103417b80               ;
net::HttpStreamFactoryImpl::Request::OnStreamFailed at
http_stream_factory_impl_request.cc:90
    0x103415782 <+530>: mov    esi, 0x92
    0x103415787 <+535>: mov    rdi, r14
    0x10341578a <+538>: call   0x1033248b0               ;
net::NetLogWithSource::EndEvent at net_log_with_source.cc:84
->  0x10341578f <+543>: add    rsp, 0x18
    0x103415793 <+547>: pop    rbx
    0x103415794 <+548>: pop    r12
    0x103415796 <+550>: pop    r13
    0x103415798 <+552>: pop    r14
    0x10341579a <+554>: pop    r15
"""

It looks like we're crashing on line 327, the last line in the function:
  326   request_->OnStreamFailed(status, used_ssl_config);
  327   net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_ON_STREAM_FAILED);

[Zhongyi Shi, 2017-03-16 18:47:39]

JobController will be deleted in the middle. I will fix in the next patch. Sorry
about that.

[Zhongyi Shi, 2017-03-18 17:10:10]

zhongyi@chromium.org changed reviewers:
+ xunjieli@chromium.org
- eroman@chromium.org

[Zhongyi Shi, 2017-03-18 17:10:11]

I have checked out the chromium on my mac, and have it built. Yay! 

Added log to extract the QUIC_STREAM_FACTORY_JOB state when a HTTP_STREAM_JOB is
BOUND to it. So that even if the QUIC_STREAM_FACTORY_JOB might be stuck earlier
with no events captured in NetLog, we should be able to get more states. 

Feel free to let me know what else I need to add. Since QUIC is not fully back
on, we'll repro the issue on Monday. So still have time to add more logging,
checks, in my build.

[Zhongyi Shi, 2017-03-23 23:47:56]

Description was changed from

==========
[DO NOT SUBMIT, PATCH on commit 7fa349e632a44c152b05ca6a66ade5f2e5b3f139]

Add more Quic related NetLogs for debugging crbug.com/700617.
1. More granular states in HTTP_STREAM_JOB:
if it's a alt job, whether it uses exisiting active session,
                        or it binds to active jobs
                        or it creates new QuicStreamFactory::Job
2. More logging when alt job is deleted.
3. Seperate QUIC_STREAM_FACTORY_JOB net_log, with granular states logging.
4. QUIC_STREAM_FACTORY_JOB and HTTP_STREAM_JOB(alt_job) is now linked.

BUG=700617
==========

to

==========
[DO NOT SUBMIT, PATCH on commit 7fa349e632a44c152b05ca6a66ade5f2e5b3f139]

Add more Quic related NetLogs for debugging crbug.com/700617.
1. More granular states in HTTP_STREAM_JOB:
if it's a alt job, whether it uses exisiting active session,
                        or it binds to active jobs
                        or it creates new QuicStreamFactory::Job
2. More logging when alt job is deleted.
3. Seperate QUIC_STREAM_FACTORY_JOB net_log, with granular states logging.
4. QUIC_STREAM_FACTORY_JOB and HTTP_STREAM_JOB(alt_job) is now linked.

BUG=700617
==========