Display content_shell error messages.

Display content_shell error messages.

BUG=668196
Committed: https://crrev.com/ca8dc086777939dbf144e40feddd6e5d4957b32b
Committed: https://crrev.com/6ca5ee2fde09bd2a3798e8edf0e3dd3d3fb5de87
Cr-Original-Commit-Position: refs/heads/master@{#435954}
Cr-Commit-Position: refs/heads/master@{#437453}

[Jack Bates, 2016-11-23 18:43:46]

Description was changed from

==========
Display content_shell output if it failed to start.

This change switches content_shell logging back to stderr,
instead of logging to content_shell.log.
The layout tests can then capture and display these messages.

BUG=668196
==========

to

==========
Display content_shell output if it failed to start.

This change switches content_shell logging back to stderr,
instead of logging to content_shell.log.
The layout tests can then capture and display these messages.

BUG=668196
==========

[Jack Bates, 2016-11-23 18:43:47]

jack@nottheoilrig.com changed reviewers:
+ dpranke@chromium.org

[Jack Bates, 2016-11-23 19:04:42]

With this change, when I run the layout tests, I see:

> Running 4 content_shells in parallel.
> 
> ERR: [...:ERROR:fontconfig_util_linux.cc(88)] You are missing
/usr/share/fonts/opentype/ipafont-gothic/ipag.ttf. Try re-running
build/install-build-deps.sh. Also see
https://chromium.googlesource.com/chromium/src/+/master/docs/layout_tests_lin...
> Failed to start the content_shell process: 
> content_shell took too long to startup.
> [1/43170] http/...d.html failed unexpectedly (content_shell crashed
[pid=30750])

I think it would help in identifying the problem?

[Dirk Pranke, 2016-11-29 02:20:48]

https://codereview.chromium.org/2525033003/diff/1/content/shell/app/shell_mai...
File content/shell/app/shell_main_delegate.cc (left):

https://codereview.chromium.org/2525033003/diff/1/content/shell/app/shell_mai...
content/shell/app/shell_main_delegate.cc:145: InitLogging();
You should probably leave the logging code in and have:

if (!command_line.HasSwitch(switches::kRunLayoutTest))
  InitLogging();

So that we still get content_shell.log in the normal case.

https://codereview.chromium.org/2525033003/diff/1/third_party/WebKit/Tools/Sc...
File third_party/WebKit/Tools/Scripts/webkitpy/layout_tests/port/driver.py
(right):

https://codereview.chromium.org/2525033003/diff/1/third_party/WebKit/Tools/Sc...
third_party/WebKit/Tools/Scripts/webkitpy/layout_tests/port/driver.py:347:
_log.error('Failed to start the %s process: \n%s', server_process.name(),
output)
Doesn't this result in double-logging things, since we're logging output on line
347 as well?

[Jack Bates, 2016-12-01 17:37:02]

Description was changed from

==========
Display content_shell output if it failed to start.

This change switches content_shell logging back to stderr,
instead of logging to content_shell.log.
The layout tests can then capture and display these messages.

BUG=668196
==========

to

==========
Display content_shell error messages.

When run with --run-layout-tests, this change switches content_shell
logging back to stderr, instead of logging to content_shell.log.
The layout tests can then capture and display any messages.

BUG=668196
==========

[Jack Bates, 2016-12-01 17:47:38]

Thank you for your feedback. I uploaded a new patch.

https://codereview.chromium.org/2525033003/diff/1/content/shell/app/shell_mai...
File content/shell/app/shell_main_delegate.cc (left):

https://codereview.chromium.org/2525033003/diff/1/content/shell/app/shell_mai...
content/shell/app/shell_main_delegate.cc:145: InitLogging();
On 2016/11/29 02:20:48, Dirk Pranke wrote:
> You should probably leave the logging code in and have:
> 
> if (!command_line.HasSwitch(switches::kRunLayoutTest))
>   InitLogging();
> 
> So that we still get content_shell.log in the normal case.

Done.

https://codereview.chromium.org/2525033003/diff/1/third_party/WebKit/Tools/Sc...
File third_party/WebKit/Tools/Scripts/webkitpy/layout_tests/port/driver.py
(right):

https://codereview.chromium.org/2525033003/diff/1/third_party/WebKit/Tools/Sc...
third_party/WebKit/Tools/Scripts/webkitpy/layout_tests/port/driver.py:347:
_log.error('Failed to start the %s process: \n%s', server_process.name(),
output)
On 2016/11/29 02:20:48, Dirk Pranke wrote:
> Doesn't this result in double-logging things, since we're logging output on
line
> 347 as well?

Oops! Yes. How did I miss that? Thank you. I uploaded a new patch.

[Dirk Pranke, 2016-12-01 20:48:45]

dpranke@chromium.org changed reviewers:
+ peter@chromium.org

[Dirk Pranke, 2016-12-01 20:48:46]

lgtm.

Peter, can you do an OWNERS review?

[Peter Beverloo, 2016-12-02 11:39:15]

This is great! Thanks for doing this :)

lgtm

[Jack Bates, 2016-12-02 15:10:58]

The CQ bit was checked by jack@nottheoilrig.com

[commit-bot: I haz the power, 2016-12-02 15:11:17]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-02 16:50:40]

CQ is committing da patch.

Bot data: {"patchset_id": 20001, "attempt_start_ts": 1480691458335500,
"parent_rev": "8316db9675a668d550d510890713fa369afc23ff", "commit_rev":
"91171e06924fc21a6ebc53cbf0b195d5930c5a45"}

[commit-bot: I haz the power, 2016-12-02 16:51:13]

Description was changed from

==========
Display content_shell error messages.

When run with --run-layout-tests, this change switches content_shell
logging back to stderr, instead of logging to content_shell.log.
The layout tests can then capture and display any messages.

BUG=668196
==========

to

==========
Display content_shell error messages.

When run with --run-layout-tests, this change switches content_shell
logging back to stderr, instead of logging to content_shell.log.
The layout tests can then capture and display any messages.

BUG=668196
==========

[commit-bot: I haz the power, 2016-12-02 16:51:14]

Committed patchset #2 (id:20001)

[commit-bot: I haz the power, 2016-12-02 16:55:06]

Description was changed from

==========
Display content_shell error messages.

When run with --run-layout-tests, this change switches content_shell
logging back to stderr, instead of logging to content_shell.log.
The layout tests can then capture and display any messages.

BUG=668196
==========

to

==========
Display content_shell error messages.

When run with --run-layout-tests, this change switches content_shell
logging back to stderr, instead of logging to content_shell.log.
The layout tests can then capture and display any messages.

BUG=668196

Committed: https://crrev.com/ca8dc086777939dbf144e40feddd6e5d4957b32b
Cr-Commit-Position: refs/heads/master@{#435954}
==========

[commit-bot: I haz the power, 2016-12-02 16:55:07]

Patchset 2 (id:??) landed as
https://crrev.com/ca8dc086777939dbf144e40feddd6e5d4957b32b
Cr-Commit-Position: refs/heads/master@{#435954}

[jbroman, 2016-12-02 19:02:57]

A revert of this CL (patchset #2 id:20001) has been created in
https://codereview.chromium.org/2548453004/ by jbroman@chromium.org.

The reason for reverting is: Suspected of causing crashes in win_chromium_rel_ng
runs.

e.g.
https://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_rel...

10:05:33.718 4648   [1202/100532.865:FATAL:sandbox_win.cc(789)] Check failed:
base::FilePath(logging::GetLogFileFullPath()).IsAbsolute(). 
10:05:33.718 4648   Backtrace:
10:05:33.718 4648   	base::debug::StackTrace::StackTrace [0x01DB6877+23]
10:05:33.718 4648   	logging::LogMessage::~LogMessage [0x01D64C61+49]
10:05:33.718 4648   	content::StartSandboxedProcess [0x01012CE2+1101]
10:05:33.718 4648   	content::ChildProcessLauncher::Launch [0x01A3BB32+983]
10:05:33.718 4648   	Invoke< ?? :: ?? :: ?? ::Callback<void ,base::$00$00,enum
content::BrowserThread::ID const &,int const
&,ID::SandboxedProcessLauncherDelegate * const
&,mojo::edk::ScopedPlatformHandle,base::CommandLine * const &> const &>
[0x01A3B0CC+41]
10:05:33.718 4648  
	??$RunImpl@ABQ6AXABV?$Callback@$$A6AX$$TVProcess@base@@H@Z$00$00@base@@W4ID@BrowserThread@content@@HPAVSandboxedProcessLauncherDelegate@5@VScopedPlatformHandle@edk@mojo@@PAVCommandLine@2@@ZABV?$tuple@V?$Callback@$$A6AX$$TVProcess@base@@H@Z$00$00@base@@W4I
[0x01A3B190+53]
10:05:33.718 4648   	base::internal::Invoker<base::internal::BindState<void
,ZV12::nternal,ZV12::CommandLine *>,void __cdecl(void)>::Run [0x01A3BED8+22]
10:05:33.718 4648   	base::debug::TaskAnnotator::RunTask [0x01DE32FE+286]
10:05:33.718 4648   	base::MessageLoop::RunTask [0x01DA54EC+1228]
10:05:33.718 4648   	base::MessageLoop::DoWork [0x01DA4493+611]
10:05:33.718 4648   	base::MessagePumpDefault::Run [0x01DE518B+219]
10:05:33.718 4648   	base::MessageLoop::RunHandler [0x01DA5011+305]
10:05:33.718 4648   	base::RunLoop::Run [0x01DB66AA+122]
10:05:33.718 4648   	base::Thread::Run [0x01DA1B6D+173]
10:05:33.718 4648   	content::BrowserThreadImpl::ProcessLauncherThreadRun
[0x01A1F71C+30]
10:05:33.718 4648   	content::BrowserThreadImpl::Run [0x01A1F860+222]
10:05:33.718 4648   	base::Thread::ThreadMain [0x01DA266E+622]
10:05:33.719 4648   	base::PlatformThread::Sleep [0x01D66982+290]
10:05:33.719 4648   	BaseThreadInitThunk [0x7538338A+18]
10:05:33.719 4648   	RtlInitializeExceptionChain [0x77359A02+99]
10:05:33.719 4648   	RtlInitializeExceptionChain [0x773599D5+54].

[Jack Bates, 2016-12-04 23:10:03]

On 2016/12/02 19:02:57, jbroman wrote:
> A revert of this CL (patchset #2 id:20001) has been created in
> https://codereview.chromium.org/2548453004/ by mailto:jbroman@chromium.org.
> 
> The reason for reverting is: Suspected of causing crashes in
win_chromium_rel_ng
> runs.
> 
> e.g.
>
https://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_rel...
> 
> 10:05:33.718 4648   [1202/100532.865:FATAL:sandbox_win.cc(789)] Check failed:
> base::FilePath(logging::GetLogFileFullPath()).IsAbsolute(). 
> 10:05:33.718 4648   Backtrace:
> 10:05:33.718 4648   	base::debug::StackTrace::StackTrace [0x01DB6877+23]
> 10:05:33.718 4648   	logging::LogMessage::~LogMessage [0x01D64C61+49]
> 10:05:33.718 4648   	content::StartSandboxedProcess [0x01012CE2+1101]
> 10:05:33.718 4648   	content::ChildProcessLauncher::Launch [0x01A3BB32+983]
> 10:05:33.718 4648   	Invoke< ?? :: ?? :: ?? ::Callback<void ,base::$00$00,enum
> content::BrowserThread::ID const &,int const
> &,ID::SandboxedProcessLauncherDelegate * const
> &,mojo::edk::ScopedPlatformHandle,base::CommandLine * const &> const &>
> [0x01A3B0CC+41]
> 10:05:33.718 4648  
>
	??$RunImpl@ABQ6AXABV?$Callback@$$A6AX$$TVProcess@base@@H@Z$00$00@base@@W4ID@BrowserThread@content@@HPAVSandboxedProcessLauncherDelegate@5@VScopedPlatformHandle@edk@mojo@@PAVCommandLine@2@@ZABV?$tuple@V?$Callback@$$A6AX$$TVProcess@base@@H@Z$00$00@base@@W4I
> [0x01A3B190+53]
> 10:05:33.718 4648   	base::internal::Invoker<base::internal::BindState<void
> ,ZV12::nternal,ZV12::CommandLine *>,void __cdecl(void)>::Run [0x01A3BED8+22]
> 10:05:33.718 4648   	base::debug::TaskAnnotator::RunTask [0x01DE32FE+286]
> 10:05:33.718 4648   	base::MessageLoop::RunTask [0x01DA54EC+1228]
> 10:05:33.718 4648   	base::MessageLoop::DoWork [0x01DA4493+611]
> 10:05:33.718 4648   	base::MessagePumpDefault::Run [0x01DE518B+219]
> 10:05:33.718 4648   	base::MessageLoop::RunHandler [0x01DA5011+305]
> 10:05:33.718 4648   	base::RunLoop::Run [0x01DB66AA+122]
> 10:05:33.718 4648   	base::Thread::Run [0x01DA1B6D+173]
> 10:05:33.718 4648   	content::BrowserThreadImpl::ProcessLauncherThreadRun
> [0x01A1F71C+30]
> 10:05:33.718 4648   	content::BrowserThreadImpl::Run [0x01A1F860+222]
> 10:05:33.718 4648   	base::Thread::ThreadMain [0x01DA266E+622]
> 10:05:33.719 4648   	base::PlatformThread::Sleep [0x01D66982+290]
> 10:05:33.719 4648   	BaseThreadInitThunk [0x7538338A+18]
> 10:05:33.719 4648   	RtlInitializeExceptionChain [0x77359A02+99]
> 10:05:33.719 4648   	RtlInitializeExceptionChain [0x773599D5+54].

I think what's going on here is:
On Windows the default logging destination is LOG_TO_FILE [1][2] which is why
logging::IsLoggingToFileEnabled() is true [3][4].
There is a default log file (debug.log [5][6][7]) but it's not initialized until
InitializeLogFileHandle(), which is called from logging::InitLogging() [8] and
LogMessage::~LogMessage() [9].
So if you don't call logging::InitLogging(), then
logging::IsLoggingToFileEnabled() is true but
DCHECK(base::FilePath(logging::GetLogFileFullPath()).IsAbsolute()) fails [10].
(This is what I assume is going on.)

One solution is to leave shell_main_delegate.cc InitLogging() contingent on
!command_line.HasSwitch(switches::kRunLayoutTest), but always call
logging::InitLogging().
I'll upload another patch with this change.

[1]
https://chromium.googlesource.com/chromium/src.git/+/master/base/logging.cc#97
[2]
https://chromium.googlesource.com/chromium/src.git/+/master/base/logging.h#165
[3]
https://chromium.googlesource.com/chromium/src.git/+/master/content/common/sa...
[4]
https://chromium.googlesource.com/chromium/src.git/+/master/base/logging.cc#933
[5]
https://chromium.googlesource.com/chromium/src.git/+/master/base/logging.h#224
[6]
https://chromium.googlesource.com/chromium/src.git/+/master/base/logging.cc#180
[7]
https://chromium.googlesource.com/chromium/src.git/+/master/base/logging.cc#278
[8]
https://chromium.googlesource.com/chromium/src.git/+/master/base/logging.cc#395
[9]
https://chromium.googlesource.com/chromium/src.git/+/master/base/logging.cc#709
[10]
https://chromium.googlesource.com/chromium/src.git/+/master/content/common/sa...

[Jack Bates, 2016-12-04 23:15:28]

Description was changed from

==========
Display content_shell error messages.

When run with --run-layout-tests, this change switches content_shell
logging back to stderr, instead of logging to content_shell.log.
The layout tests can then capture and display any messages.

BUG=668196

Committed: https://crrev.com/ca8dc086777939dbf144e40feddd6e5d4957b32b
Cr-Commit-Position: refs/heads/master@{#435954}
==========

to

==========
Display content_shell error messages.

When run with --run-layout-tests, this change switches content_shell
logging back to stderr, instead of logging to content_shell.log.
The layout tests can then capture and display any messages.

BUG=668196

Committed: https://crrev.com/ca8dc086777939dbf144e40feddd6e5d4957b32b
Cr-Commit-Position: refs/heads/master@{#435954}
==========

[Dirk Pranke, 2016-12-08 22:09:21]

https://codereview.chromium.org/2525033003/diff/40001/content/shell/app/shell...
File content/shell/app/shell_main_delegate.cc (right):

https://codereview.chromium.org/2525033003/diff/40001/content/shell/app/shell...
content/shell/app/shell_main_delegate.cc:153: }
Having a routine in this file called InitLogging() that is called in one case,
and a routine not in this file called InitLogging that is called in the other is
fairly confusing. 

Does it work if you change this to:

    bool should_log_to_stderr =
command_line.HasSwitch(switches::kRunLayoutTest);
    InitLogging(should_log_to_stderr);

and change the implementation of InitLogging() accordingly?

[Jack Bates, 2016-12-08 23:33:23]

Description was changed from

==========
Display content_shell error messages.

When run with --run-layout-tests, this change switches content_shell
logging back to stderr, instead of logging to content_shell.log.
The layout tests can then capture and display any messages.

BUG=668196

Committed: https://crrev.com/ca8dc086777939dbf144e40feddd6e5d4957b32b
Cr-Commit-Position: refs/heads/master@{#435954}
==========

to

==========
Display content_shell error messages.

BUG=668196

Committed: https://crrev.com/ca8dc086777939dbf144e40feddd6e5d4957b32b
Cr-Commit-Position: refs/heads/master@{#435954}
==========

[Jack Bates, 2016-12-08 23:47:51]

On 2016/12/08 22:09:21, Dirk Pranke wrote:
>
https://codereview.chromium.org/2525033003/diff/40001/content/shell/app/shell...
> File content/shell/app/shell_main_delegate.cc (right):
> 
>
https://codereview.chromium.org/2525033003/diff/40001/content/shell/app/shell...
> content/shell/app/shell_main_delegate.cc:153: }
> Having a routine in this file called InitLogging() that is called in one case,
> and a routine not in this file called InitLogging that is called in the other
is
> fairly confusing. 
> 
> Does it work if you change this to:
> 
>     bool should_log_to_stderr =
> command_line.HasSwitch(switches::kRunLayoutTest);
>     InitLogging(should_log_to_stderr);
> 
> and change the implementation of InitLogging() accordingly?

I don't know how I didn't notice this until now, but logging_dest is currently
logging::LOG_TO_ALL, which means content_shell already logs to *both* stderr and
content_shell.log, so only the change to driver.py is needed. (I guess I just
assumed it logged to only one or the other.)
I uploaded another patch that drops all but the driver.py change.
Thanks and sorry for the unnecessary noise!

[Dirk Pranke, 2016-12-09 01:39:35]

heh. lgtm.

[Dirk Pranke, 2016-12-09 01:40:16]

The CQ bit was checked by dpranke@chromium.org

[Dirk Pranke, 2016-12-09 01:40:16]

The patchset sent to the CQ was uploaded after l-g-t-m from peter@chromium.org
Link to the patchset: https://codereview.chromium.org/2525033003/#ps60001
(title: "LOG_TO_ALL already logs to stderr")

[commit-bot: I haz the power, 2016-12-09 01:40:48]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-09 03:36:49]

CQ is committing da patch.

Bot data: {"patchset_id": 60001, "attempt_start_ts": 1481247616163610,
"parent_rev": "cd8876fae74e1940ac4883a4c60c859fbd15ecc3", "commit_rev":
"4b9b8326228d50d1b82cfc8b2d83323e6052e3e4"}

[commit-bot: I haz the power, 2016-12-09 03:37:22]

Description was changed from

==========
Display content_shell error messages.

BUG=668196

Committed: https://crrev.com/ca8dc086777939dbf144e40feddd6e5d4957b32b
Cr-Commit-Position: refs/heads/master@{#435954}
==========

to

==========
Display content_shell error messages.

BUG=668196

Committed: https://crrev.com/ca8dc086777939dbf144e40feddd6e5d4957b32b
Cr-Commit-Position: refs/heads/master@{#435954}
==========

[commit-bot: I haz the power, 2016-12-09 03:37:24]

Committed patchset #4 (id:60001)

[commit-bot: I haz the power, 2016-12-09 03:40:30]

Description was changed from

==========
Display content_shell error messages.

BUG=668196

Committed: https://crrev.com/ca8dc086777939dbf144e40feddd6e5d4957b32b
Cr-Commit-Position: refs/heads/master@{#435954}
==========

to

==========
Display content_shell error messages.

BUG=668196

Committed: https://crrev.com/ca8dc086777939dbf144e40feddd6e5d4957b32b
Committed: https://crrev.com/6ca5ee2fde09bd2a3798e8edf0e3dd3d3fb5de87
Cr-Original-Commit-Position: refs/heads/master@{#435954}
Cr-Commit-Position: refs/heads/master@{#437453}
==========

[commit-bot: I haz the power, 2016-12-09 03:40:31]

Patchset 4 (id:??) landed as
https://crrev.com/6ca5ee2fde09bd2a3798e8edf0e3dd3d3fb5de87
Cr-Commit-Position: refs/heads/master@{#437453}