net: Add more debugging code to diagnose flaky testserver failures.

BUG=96594

Review URL: https://codereview.chromium.org/12837005

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@188762 0039d316-1c4b-4281-b951-d872f2087c98

2 files changed, 48 insertions, 14 deletions

diff --git a/net/tools/testserver/testserver.py b/net/tools/testserver/testserver.py
index 44312a0..27f0f66 100755
--- a/net/tools/testserver/testserver.py
+++ b/net/tools/testserver/testserver.py
@@ -34,6 +34,10 @@ import urllib
 import urlparse
 import zlib
 
+# TODO(phajdan.jr): Remove after debugging http://crbug.com/96594 .
+sys.stdout.write('testserver.py right after std imports!\n')
+sys.stdout.flush()
+
 import echo_message
 import pyftpdlib.ftpserver
 import testserver_base
@@ -171,7 +175,8 @@ class HTTPSServer(tlslite.api.TLSSocketServerMixIn,
       # Ignore abrupt close.
       return True
     except tlslite.api.TLSError, error:
-      print "Handshake failure:", str(error)
+      sys.stdout.write("Handshake failure: %s" % str(error))
+      sys.stdout.flush()
       return False
 
 
@@ -768,7 +773,9 @@ class TestPageHandler(testserver_base.BasePageHandler):
       file_path = os.path.join(file_path, 'index.html')
 
     if not os.path.isfile(file_path):
-      print "File not found " + sub_path + " full path:" + file_path
+      sys.stdout.write("File not found " + sub_path +
+                       " full path:" + file_path + "\n")
+      sys.stdout.flush()
       self.send_error(404)
       return True
 
@@ -852,7 +859,9 @@ class TestPageHandler(testserver_base.BasePageHandler):
       file_path = os.path.join(file_path, 'index.html')
 
     if not os.path.isfile(file_path):
-      print "File not found " + sub_path + " full path:" + file_path
+      sys.stdout.write("File not found " + sub_path +
+                       " full path:" + file_path + "\n")
+      sys.stdout.flush()
       self.send_error(404)
       return True
 
@@ -1884,8 +1893,9 @@ class ServerRunner(testserver_base.TestServerRunner):
         else:
           # generate a new certificate and run an OCSP server for it.
           self.__ocsp_server = OCSPServer((host, 0), OCSPHandler)
-          print ('OCSP server started on %s:%d...' %
+          sys.stdout.write('OCSP server started on %s:%d...\n' %
               (host, self.__ocsp_server.server_port))
+          sys.stdout.flush()
 
           ocsp_der = None
           ocsp_state = None
@@ -1923,10 +1933,14 @@ class ServerRunner(testserver_base.TestServerRunner):
                              self.options.ssl_bulk_cipher,
                              self.options.record_resume,
                              self.options.tls_intolerant)
-        print 'HTTPS server started on %s:%d...' % (host, server.server_port)
+        sys.stdout.write('HTTPS server started on %s:%d...\n' %
+                         (host, server.server_port))
+        sys.stdout.flush()
       else:
         server = HTTPServer((host, port), TestPageHandler)
-        print 'HTTP server started on %s:%d...' % (host, server.server_port)
+        sys.stdout.write('HTTP server started on %s:%d...\n' %
+                         (host, server.server_port))
+        sys.stdout.flush()
 
       server.data_dir = self.__make_data_dir()
       server.file_root_url = self.options.file_root_url
@@ -1954,25 +1968,33 @@ class ServerRunner(testserver_base.TestServerRunner):
               self.options.ssl_client_ca[0] + ' exiting...')
         websocket_options.tls_client_ca = self.options.ssl_client_ca[0]
       server = WebSocketServer(websocket_options)
-      print 'WebSocket server started on %s:%d...' % (host, server.server_port)
+      sys.stdout.write('WebSocket server started on %s:%d...\n'
+                       % (host, server.server_port))
+      sys.stdout.flush()
       server_data['port'] = server.server_port
     elif self.options.server_type == SERVER_TCP_ECHO:
       # Used for generating the key (randomly) that encodes the "echo request"
       # message.
       random.seed()
       server = TCPEchoServer((host, port), TCPEchoHandler)
-      print 'Echo TCP server started on port %d...' % server.server_port
+      sys.stdout.write('Echo TCP server started on port %d...\n'
+                       % server.server_port)
+      sys.stdout.flush()
       server_data['port'] = server.server_port
     elif self.options.server_type == SERVER_UDP_ECHO:
       # Used for generating the key (randomly) that encodes the "echo request"
       # message.
       random.seed()
       server = UDPEchoServer((host, port), UDPEchoHandler)
-      print 'Echo UDP server started on port %d...' % server.server_port
+      sys.stdout.write('Echo UDP server started on port %d...\n' %
+                       server.server_port)
+      sys.stdout.flush()
       server_data['port'] = server.server_port
     elif self.options.server_type == SERVER_BASIC_AUTH_PROXY:
       server = HTTPServer((host, port), BasicAuthProxyRequestHandler)
-      print 'BasicAuthProxy server started on port %d...' % server.server_port
+      sys.stdout.write('BasicAuthProxy server started on port %d...\n' %
+                       server.server_port)
+      sys.stdout.flush()
       server_data['port'] = server.server_port
     elif self.options.server_type == SERVER_FTP:
       my_data_dir = self.__make_data_dir()
@@ -1997,7 +2019,9 @@ class ServerRunner(testserver_base.TestServerRunner):
       # Instantiate FTP server class and listen to address:port
       server = pyftpdlib.ftpserver.FTPServer((host, port), ftp_handler)
       server_data['port'] = server.socket.getsockname()[1]
-      print 'FTP server started on port %d...' % server_data['port']
+      sys.stdout.write('FTP server started on port %d...\n' %
+                       server_data['port'])
+      sys.stdout.flush()
     else:
       raise testserver_base.OptionError('unknown server type' +
           self.options.server_type)
@@ -2086,4 +2110,8 @@ class ServerRunner(testserver_base.TestServerRunner):
 
 
 if __name__ == '__main__':
+  # TODO(phajdan.jr): Remove after debugging http://crbug.com/96594 .
+  sys.stdout.write('testserver.py running!\n')
+  sys.stdout.flush()
+
   sys.exit(ServerRunner().main())
diff --git a/net/tools/testserver/testserver_base.py b/net/tools/testserver/testserver_base.py
index 455ca5c..d550537 100644
--- a/net/tools/testserver/testserver_base.py
+++ b/net/tools/testserver/testserver_base.py
@@ -232,11 +232,16 @@ class TestServerRunner(object):
   def _notify_startup_complete(self, server_data):
     # Notify the parent that we've started. (BaseServer subclasses
     # bind their sockets on construction.)
-    if self.options.startup_pipe is not None:
+    if self.options.startup_pipe is None:
+      # TODO(phajdan.jr): Remove after debugging http://crbug.com/96594 .
+      sys.stdout.write('will not send server_data (not requested)\n')
+      sys.stdout.flush()
+    else:
       server_data_json = json.dumps(server_data)
       server_data_len = len(server_data_json)
-      print 'sending server_data: %s (%d bytes)' % (
-        server_data_json, server_data_len)
+      sys.stdout.write('sending server_data: %s (%d bytes)\n' % (
+        server_data_json, server_data_len))
+      sys.stdout.flush()
       if sys.platform == 'win32':
         fd = msvcrt.open_osfhandle(self.options.startup_pipe, 0)
       else:
@@ -247,4 +252,5 @@ class TestServerRunner(object):
       # pipe is on the same machine.
       startup_pipe.write(struct.pack('=L', server_data_len))
       startup_pipe.write(server_data_json)
+      startup_pipe.flush()
       startup_pipe.close()