add debug logging for win apache issues

Tools/Scripts/webkitpy/layout_tests/servers/server_base.py

 # Copyright (C) 2011 Google Inc. All rights reserved.
 #
 # Redistribution and use in source and binary forms, with or without
 # modification, are permitted provided that the following conditions are
 # met:
 #
 #     * Redistributions of source code must retain the above copyright
 # notice, this list of conditions and the following disclaimer.
 #     * Redistributions in binary form must reproduce the above
 # copyright notice, this list of conditions and the following disclaimer
@@ skipping 58 matching lines @@
         self._mappings = {}
         self._pid_file = None
         self._start_cmd = None
 
         # Subclasses may override these fields.
         self._env = None
         self._stdout = self._executive.PIPE
         self._stderr = self._executive.PIPE
         self._process = None
         self._pid = None
+        self._error_log = None
 
     def start(self):
         """Starts the server. It is an error to start an already started server.
 
         This method also stops any stale servers started by a previous instance."""
         assert not self._pid, '%s server is already running' % self._name
 
         # Stop any stale servers left over from previous instances.
         if self._filesystem.exists(self._pid_file):
             try:
                 self._pid = int(self._filesystem.read_text_file(self._pid_file))
+                _log.debug('stale %s pid file, pid %d' % (self._name, self._pid))
                 self._stop_running_server()
             except (ValueError, UnicodeDecodeError):
                 # These could be raised if the pid file is corrupt.
                 self._remove_pid_file()
             self._pid = None
 
         self._remove_stale_logs()
         self._prepare_config()
         self._check_that_all_ports_are_available()
 
         self._pid = self._spawn_process()
 
         if self._wait_for_action(self._is_server_running_on_all_ports):
             _log.debug("%s successfully started (pid = %d)" % (self._name, self._pid))
         else:
+            self._dump_logs()
             self._stop_running_server()
             raise ServerError('Failed to start %s server' % self._name)
 
     def stop(self):
         """Stops the server. Stopping a server that isn't started is harmless."""
         actual_pid = None
         try:
             if self._filesystem.exists(self._pid_file):
                 try:
                     actual_pid = int(self._filesystem.read_text_file(self._pid_file))
@@ skipping 49 matching lines @@
         self._filesystem.write_text_file(self._pid_file, str(pid))
         return pid
 
     def _stop_running_server(self):
         self._wait_for_action(self._check_and_kill)
         if self._filesystem.exists(self._pid_file):
             self._filesystem.remove(self._pid_file)
 
     def _check_and_kill(self):
         if self._executive.check_running_pid(self._pid):
+            _log.debug('pid %d is running, killing it' % self._pid)
             host = self._port_obj.host
             self._executive.kill_process(self._pid)
             return False
+        else:
+            _log.debug('pid %d is not running' % self._pid)
+
         return True
 
     def _remove_pid_file(self):
         if self._filesystem.exists(self._pid_file):
             self._filesystem.remove(self._pid_file)
 
     def _remove_log_files(self, folder, starts_with):
         files = self._filesystem.listdir(folder)
         for file in files:
             if file.startswith(starts_with):
                 full_path = self._filesystem.join(folder, file)
                 self._filesystem.remove(full_path)
 
+    def _dump_logs(self):

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

I didn't know what "dump" meant until I read it.  copy_logs_to_stdout?  not
sure.

[Dirk Pranke, 2014/07/23 23:51:00]

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

+        _log.error('%s dumping logs' % self._name)
+        if self._process:
+            _log.error('%s returncode %s' % (self._name, str(self._process.returncode)))
+            if self._process.stderr:
+                stderr_text = self._process.stderr.read()
+                if stderr_text:
+                    _log.error('%s stderr:' % self._name)
+                    for line in stderr_text.splitlines():
+                        _log.error('  %s' % line)
+                else:
+                    _log.error('%s no stderr' % self._name)
+            else:
+                _log.error('%s no stderr handle' % self._name)
+        else:
+            _log.error('%s no process' % self._name)
+        if self._error_log:
+            error_log_text = self._filesystem.read_text_file(self._error_log)
+            if error_log_text:
+                _log.error('%s error log (%s) contents:' % (self._name, self._error_log))
+                for line in error_log_text.splitlines():
+                    _log.error('  %s' % line)
+            else:
+                _log.error('%s error log empty' % self._name)
+            _log.error('')
+        else:
+            _log.error('%s no error log' % self._name)
+
     def _wait_for_action(self, action, wait_secs=20.0, sleep_secs=1.0):
         """Repeat the action for wait_sec or until it succeeds, sleeping for sleep_secs
         in between each attempt. Returns whether it succeeded."""
         start_time = time.time()
         while time.time() - start_time < wait_secs:
             if action():
                 return True
             _log.debug("Waiting for action: %s" % action)
             time.sleep(sleep_secs)
 
         return False
 
     def _is_server_running_on_all_ports(self):
         """Returns whether the server is running on all the desired ports."""
         if not self._executive.check_running_pid(self._pid):
-            _log.debug("Server isn't running at all")
+            _log.error("Server isn't running at all")
+            self._dump_logs()
             raise ServerError("Server exited")
 
         for mapping in self._mappings:
             s = socket.socket()
             port = mapping['port']
             try:
                 s.connect(('localhost', port))
                 _log.debug("Server running on %d" % port)
             except IOError, e:
                 if e.errno not in (errno.ECONNREFUSED, errno.ECONNRESET):
                     raise
                 _log.debug("Server NOT running on %d: %s" % (port, e))
                 return False
             finally:
                 s.close()
         return True
 
     def _check_that_all_ports_are_available(self):
         for mapping in self._mappings:
             s = socket.socket()
-            s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
+            # s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)

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

Intentional?  Comment?

[Dirk Pranke, 2014/07/23 23:51:00]

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.

             port = mapping['port']
             try:
                 s.bind(('localhost', port))
             except IOError, e:
                 if e.errno in (errno.EALREADY, errno.EADDRINUSE):
                     raise ServerError('Port %d is already in use.' % port)
                 elif sys.platform == 'win32' and e.errno in (errno.WSAEACCES,):  # pylint: disable=E1101
                     raise ServerError('Port %d is already in use.' % port)
                 else:
                     raise
             finally:
                 s.close()
+        _log.debug('all ports are available')