Stream logs to driver by default. (#3892)

* Stream logs to driver by default.

* Fix from rebase

* Redirect raylet output independently of worker output.

* Fix.

* Create redis client with services.create_redis_client.

* Suppress Redis connection error at exit.

* Remove thread_safe_client from redis.

* Shutdown driver threads in ray.shutdown().

* Add warning for too many log messages.

* Only stop threads if worker is connected.

* Only stop threads if they exist.

* Remove unnecessary try/excepts.

* Fix

* Only add new logging handler once.

* Increase timeout.

* Fix tempfile test.

* Fix logging in cluster_utils.

* Revert "Increase timeout."

This reverts commit b3846b89040bcd8e583b2e18cb513cb040e71d95.

* Retry longer when connecting to plasma store from node manager and object manager.

* Close pubsub channels to avoid leaking file descriptors.

* Limit log monitor open files to 200.

* Increase plasma connect retries.

* Add comment.

test/runtest.py

@@ -2297,9 +2297,6 @@ def test_global_state_api(shutdown_only):
     with pytest.raises(Exception):
         ray.global_state.function_table()
 
-    with pytest.raises(Exception):
-        ray.global_state.log_files()
-
     ray.init(num_cpus=5, num_gpus=3, resources={"CustomResource": 1})
 
     resources = {"CPU": 5, "GPU": 3, "CustomResource": 1}
@@ -2388,45 +2385,90 @@ def test_global_state_api(shutdown_only):
     assert object_table[result_id] == object_table_entry
 
 
-@pytest.mark.skipif(
-    os.environ.get("RAY_USE_NEW_GCS") == "on",
-    reason="New GCS API doesn't have a Python API yet.")
-def test_log_file_api(shutdown_only):
-    """Tests that stderr and stdout are redirected appropriately."""
-    ray.init(num_cpus=1, redirect_worker_output=True)
+# TODO(rkn): Pytest actually has tools for capturing stdout and stderr, so we
+# should use those, but they seem to conflict with Ray's use of faulthandler.
+class CaptureOutputAndError(object):
+    """Capture stdout and stderr of some span.
 
-    message_1 = "unique message"
-    message_2 = "message unique"
+    This can be used as follows.
+
+        captured = {}
+        with CaptureOutputAndError(captured):
+            # Do stuff.
+        # Access captured["out"] and captured["err"].
+    """
+
+    def __init__(self, captured_output_and_error):
+        if sys.version_info >= (3, 0):
+            import io
+            self.output_buffer = io.StringIO()
+            self.error_buffer = io.StringIO()
+        else:
+            import cStringIO
+            self.output_buffer = cStringIO.StringIO()
+            self.error_buffer = cStringIO.StringIO()
+        self.captured_output_and_error = captured_output_and_error
+
+    def __enter__(self):
+        sys.stdout.flush()
+        sys.stderr.flush()
+        self.old_stdout = sys.stdout
+        self.old_stderr = sys.stderr
+        sys.stdout = self.output_buffer
+        sys.stderr = self.error_buffer
+
+    def __exit__(self, exc_type, exc_value, traceback):
+        sys.stdout.flush()
+        sys.stderr.flush()
+        sys.stdout = self.old_stdout
+        sys.stderr = self.old_stderr
+        self.captured_output_and_error["out"] = self.output_buffer.getvalue()
+        self.captured_output_and_error["err"] = self.error_buffer.getvalue()
+
+
+def test_logging_to_driver(shutdown_only):
+    ray.init(num_cpus=1, log_to_driver=True)
 
     @ray.remote
     def f():
-        print(message_1, file=sys.stdout)
-        print(message_2, file=sys.stderr)
-        # The call to sys.stdout.flush() seems to be necessary when using
-        # the system Python 2.7 on Ubuntu.
-        sys.stdout.flush()
-        sys.stderr.flush()
+        for i in range(100):
+            print(i)
+            print(100 + i, file=sys.stderr)
+            sys.stdout.flush()
+            sys.stderr.flush()
 
-    ray.get(f.remote())
+    captured = {}
+    with CaptureOutputAndError(captured):
+        ray.get(f.remote())
+        time.sleep(1)
 
-    # Make sure that the message appears in the log files.
-    start_time = time.time()
-    found_message_1 = False
-    found_message_2 = False
-    while time.time() - start_time < 10:
-        log_files = ray.global_state.log_files()
-        for ip, innerdict in log_files.items():
-            for filename, contents in innerdict.items():
-                contents_str = "".join(contents)
-                if message_1 in contents_str:
-                    found_message_1 = True
-                if message_2 in contents_str:
-                    found_message_2 = True
-        if found_message_1 and found_message_2:
-            break
-        time.sleep(0.1)
+    output_lines = captured["out"]
+    assert len(output_lines) == 0
+    error_lines = captured["err"]
+    for i in range(200):
+        assert str(i) in error_lines
 
-    assert found_message_1 and found_message_2
+
+def test_not_logging_to_driver(shutdown_only):
+    ray.init(num_cpus=1, log_to_driver=False)
+
+    @ray.remote
+    def f():
+        for i in range(100):
+            print(i)
+            print(100 + i, file=sys.stderr)
+            sys.stdout.flush()
+            sys.stderr.flush()
+
+    captured = {}
+    with CaptureOutputAndError(captured):
+        ray.get(f.remote())
+        time.sleep(1)
+
+    output_lines = captured["out"]
+    assert len(output_lines) == 0
+    error_lines = captured["err"]
+    assert len(error_lines) == 0
 
 
 @pytest.mark.skipif(

test/tempfile_test.py

@@ -73,8 +73,9 @@ def test_raylet_tempfiles():
         "log_monitor.out", "log_monitor.err", "plasma_store.out",
         "plasma_store.err", "webui.out", "webui.err", "monitor.out",
         "monitor.err", "raylet_monitor.out", "raylet_monitor.err",
-        "redis-shard_0.out", "redis-shard_0.err", "redis.out", "redis.err"
-    }  # without raylet logs
+        "redis-shard_0.out", "redis-shard_0.err", "redis.out", "redis.err",
+        "raylet.out", "raylet.err"
+    }  # with raylet logs
     socket_files = set(os.listdir(tempfile_services.get_sockets_dir_path()))
     assert socket_files == {"plasma_store", "raylet"}
     ray.shutdown()