add debug logging for win apache issues

Add some debug logging for win apache issues in run-webkit-tests.

R=eseidel@chromium.org
BUG=378444
Committed: https://src.chromium.org/viewvc/blink?view=rev&revision=178801

[Dirk Pranke, 2014-07-23 23:21:11]

https://codereview.chromium.org/413063002/diff/1/Tools/Scripts/webkitpy/layou...
File Tools/Scripts/webkitpy/layout_tests/servers/apache_http.py (right):

https://codereview.chromium.org/413063002/diff/1/Tools/Scripts/webkitpy/layou...
Tools/Scripts/webkitpy/layout_tests/servers/apache_http.py:47:
self._log_prefixes = ('access_log', 'error_log')
The fact that this line was missing means that we were never cleaning up old
logs ...

https://codereview.chromium.org/413063002/diff/1/Tools/Scripts/webkitpy/layou...
Tools/Scripts/webkitpy/layout_tests/servers/apache_http.py:129: self._process =
self._executive.popen(self._start_cmd, stderr=self._executive.PIPE)
This being missing meant that stderr logging was going off into the ether (I
think)

https://codereview.chromium.org/413063002/diff/1/Tools/Scripts/webkitpy/layou...
File Tools/Scripts/webkitpy/layout_tests/servers/server_base.py (right):

https://codereview.chromium.org/413063002/diff/1/Tools/Scripts/webkitpy/layou...
Tools/Scripts/webkitpy/layout_tests/servers/server_base.py:262: #
s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
I think if we set SO_REUSEADDR, on windows this was causing python to bind to a
socket that was already in use (which is bad), and so this check was not working
properly. 

Then, when we started apache, it would bail out almost immediately but because
we were throwing away the stderr output, we weren't seeing anything.

My current hypothesis is that some other process is bound to one of the ports,
possibly a python process like the buildbot slave.

[eseidel, 2014-07-23 23:29:23]

lgtm

https://codereview.chromium.org/413063002/diff/20001/Tools/Scripts/webkitpy/l...
File Tools/Scripts/webkitpy/layout_tests/servers/apache_http.py (right):

https://codereview.chromium.org/413063002/diff/20001/Tools/Scripts/webkitpy/l...
Tools/Scripts/webkitpy/layout_tests/servers/apache_http.py:65: self._access_log
= self._filesystem.join(output_dir, "access_log.txt")
I might have added _path to these.

https://codereview.chromium.org/413063002/diff/20001/Tools/Scripts/webkitpy/l...
File Tools/Scripts/webkitpy/layout_tests/servers/server_base.py (right):

https://codereview.chromium.org/413063002/diff/20001/Tools/Scripts/webkitpy/l...
Tools/Scripts/webkitpy/layout_tests/servers/server_base.py:197: def
_dump_logs(self):
I didn't know what "dump" meant until I read it.  copy_logs_to_stdout?  not
sure.

https://codereview.chromium.org/413063002/diff/20001/Tools/Scripts/webkitpy/l...
Tools/Scripts/webkitpy/layout_tests/servers/server_base.py:262: #
s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
Intentional?  Comment?

[Dirk Pranke, 2014-07-23 23:51:01]

https://codereview.chromium.org/413063002/diff/20001/Tools/Scripts/webkitpy/l...
File Tools/Scripts/webkitpy/layout_tests/servers/apache_http.py (right):

https://codereview.chromium.org/413063002/diff/20001/Tools/Scripts/webkitpy/l...
Tools/Scripts/webkitpy/layout_tests/servers/apache_http.py:65: self._access_log
= self._filesystem.join(output_dir, "access_log.txt")
On 2014/07/23 23:29:23, eseidel wrote:
> I might have added _path to these.

Will fix.

https://codereview.chromium.org/413063002/diff/20001/Tools/Scripts/webkitpy/l...
File Tools/Scripts/webkitpy/layout_tests/servers/server_base.py (right):

https://codereview.chromium.org/413063002/diff/20001/Tools/Scripts/webkitpy/l...
Tools/Scripts/webkitpy/layout_tests/servers/server_base.py:197: def
_dump_logs(self):
On 2014/07/23 23:29:23, eseidel wrote:
> I didn't know what "dump" meant until I read it.  copy_logs_to_stdout?  not
> sure.

I thought dump was fairly conventional, but maybe I'm old :). Will change to
something better.

https://codereview.chromium.org/413063002/diff/20001/Tools/Scripts/webkitpy/l...
Tools/Scripts/webkitpy/layout_tests/servers/server_base.py:262: #
s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
On 2014/07/23 23:29:23, eseidel wrote:
> Intentional?  Comment?

Definitely intentional; see the comments in patchset #1. I think this was
causing the bind() to succeed even if the port was already in use. On unix this
doesn't happen, but I think win might be buggy.

I'm a bit concerned that this might cause problems in the other direction if we
have sockets that are still in time_wait, but hopefully the o/s will deal with
this for us. We'll see.

[Dirk Pranke, 2014-07-24 00:01:08]

The CQ bit was checked by dpranke@chromium.org

[Dirk Pranke, 2014-07-24 00:01:15]

The CQ bit was unchecked by dpranke@chromium.org

[Dirk Pranke, 2014-07-24 00:58:17]

The CQ bit was checked by dpranke@chromium.org

[commit-bot: I haz the power, 2014-07-24 00:59:52]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/dpranke@chromium.org/413063002/40001

[commit-bot: I haz the power, 2014-07-24 02:13:28]

FYI, CQ is re-trying this CL (attempt #1).
The failing builders are:
  win_blink_rel on tryserver.blink
(http://build.chromium.org/p/tryserver.blink/builders/win_blink_rel/builds/18608)

[commit-bot: I haz the power, 2014-07-24 02:49:16]

Change committed as 178801

[jsbell, 2014-08-01 19:14:51]

On 2014/07/24 02:49:16, I haz the power (commit-bot) wrote:
> Change committed as 178801

Ugh, the removal of s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
means I need to wait an indeterminate amount of time between runs for the socket
to be freed up on my linux box, otherwise port is reported as still in use.

Can we restore that line, or scope it to !self._is_win ?

[Dirk Pranke, 2014-08-01 21:56:17]

On 2014/08/01 19:14:51, jsbell wrote:
> On 2014/07/24 02:49:16, I haz the power (commit-bot) wrote:
> > Change committed as 178801
> 
> Ugh, the removal of s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
> means I need to wait an indeterminate amount of time between runs for the
socket
> to be freed up on my linux box, otherwise port is reported as still in use.
> 
> Can we restore that line, or scope it to !self._is_win ?

Yup, I definitely thought this might be a problem on unix. We should scope it to
_is_win. I don't think it's safe to add it back on win yet.