[Serve] Add logger with backend and replica tags #14251

architkulkarni · 2021-02-22T16:35:14Z

Why are these changes needed?

This PR adds a new API method serve.get_backend_logger(). When called from a backend, it returns a logger which prepends the backend tag and replica tag to each log line.

class Counter:
    def __init__(self):
        self.logger = serve.get_backend_logger()
        self.count = 0

    def __call__(self, request):
        self.count += 1
        self.logger.info(f"count: {self.count}")
        return {"count": self.count}

The PR also includes an end-to-end tutorial for filtering Ray logs by backend tag using Loki and Grafana.

Related issue number

Closes #13917
Closes #13916

Checks

I've run scripts/format.sh to lint the changes in this PR.
I've included any doc changes needed for https://docs.ray.io/en/master/.
I've made sure the tests are passing. Note that there might be a few flaky tests, see the recent failures at https://flakey-tests.ray.io/
Testing Strategy
- Unit tests
- Release tests
- This PR is not tested :(

simon-mo · 2021-02-22T18:09:07Z

I wonder if this can a bit more magical and easier to use:

logger = logging.getLogger("serve")

class MyBackend:
    def __call__(self, ..):
        logger.info("...")

architkulkarni · 2021-02-22T23:45:58Z

That would be really cool @simon-mo, do you have an idea of how to implement that? I guess we would need to wrap the standard python logger and implement each method .info(), .debug(), etc, which seems complicated but maybe isn't that bad.

edoakes · 2021-02-23T00:08:15Z

doc/source/serve/deployment.rst

+  For an general overview of logging in Ray, see `Ray Logging <../ray-logging.html>`__.
+
+When looking through log files of your Ray Serve application, it is useful to know which backend and replica each log line originated from.
+To automatically tag your logs with the current backend tag and replica tag (of the form ``backend_tag#<random letters>``), use the following function:
+
+.. autofunction:: ray.serve.get_backend_logger
+
+To write your own custom logger using Python's ``logging`` package, you may find the following two methods useful:
+
+.. autofunction:: ray.serve.get_current_backend_tag
+.. autofunction:: ray.serve.get_current_replica_tag


I'd add a subsection here saying "configuring logger" or something, then another below that says "Loki Tutorial"

edoakes · 2021-02-23T00:08:56Z

doc/source/serve/deployment.rst

+
+Ray Serve logs can be ingested by your favorite external logging agent.  Ray logs from the current session are exported to the directory `/tmp/ray/session_latest/logs` and remain there until the next session starts.
+
+Here is a quick walkthrough of how to explore and filter your logs using `Loki <https://grafana.com/oss/loki/>`__.  


Note here that we'll set it up manually but it's much easier to configure on kubernetes. Actually, it might be worth having another tutorial on k8s. We can do that in the future.

edoakes · 2021-02-23T00:10:09Z

python/ray/serve/tests/test_api.py

@@ -1012,6 +1012,29 @@ def f(starlette_request):
    }


+def test_backend_logger(serve_instance):
+    # Tests that that backend logger can be created and used without errors.
+    # Does not test the correctness of the log output.


It's probably worth testing this to avoid regressions. Can we redirect the logger to a tempfile and read that file or something similar?

simon-mo · 2021-02-23T01:22:26Z

@architkulkarni the heavily lifting is already done by ray_logging.py wrote by @rkooo567.

You can just add this

diff --git a/python/ray/serve/backend_worker.py b/python/ray/serve/backend_worker.py
index 5740cf4f5..977cde45b 100644
--- a/python/ray/serve/backend_worker.py
+++ b/python/ray/serve/backend_worker.py
@@ -1,4 +1,5 @@
 import asyncio
+import logging
 import traceback
 import inspect
 from collections.abc import Iterable
@@ -258,6 +259,13 @@ class RayServeReplica:
 
         self.restart_counter.record(1)
 
+        ray_logger = logging.getLogger("ray")
+        for handler in ray_logger.handlers:
+            handler.setFormatter(
+                logging.Formatter(
+                    handler.formatter._fmt +
+                    f" component=serve backend={self.backend_tag} replica={self.replica_tag}"
+                ))
         asyncio.get_event_loop().create_task(self.main_loop())
 
     def get_runner_method(self, request_item: Query) -> Callable:

and ask user to use the ray logger:

logger = logging.getLogger("ray")

class Counter:
    def __init__(self):
        self.count = 0

    def __call__(self, request):
        self.count += 1
        logger.info(f"count: {self.count}")
        return {"count": self.count}

the context can be automatically filled in.

...
(pid=39154) 2021-02-22 17:19:31,201	INFO a.py:17 -- count: 10 component=serve backend=my_backend replica=my_backend#BmnjUg

This eliminate the need for the explicit get_backend_logger and make user's code cleaner.

Additionally, I think we should put get_backend_tag and others behind a context API. Something like serve.get_context().backend_tag or something.

simon-mo

Let's make sure to make the following changes.

Use ray logger
move get_current_x -> some sort of context API

simon-mo · 2021-02-25T02:26:30Z

python/ray/serve/api.py


+def get_backend_context():


@edoakes thoughts on this API?

Just for context, I based it off the API for get_runtime_context() in Ray Core: https://docs.ray.io/en/master/package-ref.html#runtime-context-apis.

simon-mo · 2021-02-25T02:27:20Z

python/ray/serve/backend_worker.py

+        ray_logger = logging.getLogger("ray")
+        for handler in ray_logger.handlers:
+            handler.setFormatter(
+                logging.Formatter(
+                    handler.formatter._fmt +
+                    f" component=serve backend={self.backend_tag} "
+                    f"replica={self.replica_tag}"))
+


@rkooo567 I want to make sure this ok for the ray logging stack. Thoughts?

simon-mo · 2021-02-25T02:29:49Z

python/ray/serve/api.py

+        backend_tag = _INTERNAL_REPLICA_CONTEXT.backend_tag
+        replica_tag = _INTERNAL_REPLICA_CONTEXT.replica_tag
+
+        return BackendContext(backend_tag, replica_tag)


can we just merge InternalReplicaContext and BackendContext? You can make the controller_name a private field _internal_controller_name or something. So we don't have an extra data structure that's just a subset of InternalReplicaContext.

additionally, naming wise, this is ReplicaContext, not BackendContext because it contains the replica_tag.

Yup, that makes a lot of sense

architkulkarni · 2021-02-25T17:41:13Z

Let me also move the doc image from this repo to the external images repo.

simon-mo · 2021-02-26T18:28:51Z

doc/source/serve/deployment.rst

+
+.. code-block:: bash
+
+  INFO -- Some info! component=serve backend=my_backend replica=my_backend#krcwoa


can you update this? it should print ray logging style now

Thanks, good catch. Updated

architkulkarni added 3 commits February 22, 2021 01:31

add serve logger and docs

be130e1

remove extra file

fa6232a

update example

b5f7e49

architkulkarni requested a review from simon-mo February 22, 2021 16:35

architkulkarni assigned edoakes Feb 22, 2021

edoakes reviewed Feb 23, 2021

View reviewed changes

simon-mo requested changes Feb 23, 2021

View reviewed changes

architkulkarni added 2 commits February 24, 2021 11:56

address comments

f2b3c8a

lint

b555c26

architkulkarni requested a review from simon-mo February 24, 2021 20:38

lint

893142c

simon-mo reviewed Feb 25, 2021

View reviewed changes

architkulkarni added the @author-action-required The PR author is responsible for the next step. Remove tag to send back to the reviewer. label Feb 25, 2021

edoakes assigned simon-mo and unassigned edoakes Feb 25, 2021

architkulkarni added 4 commits February 25, 2021 16:37

merge INTERNAL_REPLICA_CONTEXT and backend_context

c9cf1a7

move doc image to external repo

34beb0b

lint

dadbd12

fix image link

c50b753

architkulkarni added tests-ok The tagger certifies test failures are unrelated and assumes personal liability. and removed @author-action-required The PR author is responsible for the next step. Remove tag to send back to the reviewer. labels Feb 26, 2021

architkulkarni requested a review from simon-mo February 26, 2021 17:09

simon-mo approved these changes Feb 26, 2021

View reviewed changes

update log line in doc

ff86b0b

simon-mo merged commit f9364b1 into ray-project:master Feb 26, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Serve] Add logger with backend and replica tags #14251

[Serve] Add logger with backend and replica tags #14251

architkulkarni commented Feb 22, 2021 •

edited by edoakes

Loading

simon-mo commented Feb 22, 2021

architkulkarni commented Feb 22, 2021

edoakes Feb 23, 2021

edoakes Feb 23, 2021

edoakes Feb 23, 2021

simon-mo commented Feb 23, 2021

simon-mo left a comment

simon-mo Feb 25, 2021

architkulkarni Feb 25, 2021

simon-mo Feb 25, 2021

simon-mo Feb 25, 2021

architkulkarni Feb 25, 2021

architkulkarni commented Feb 25, 2021

simon-mo Feb 26, 2021

architkulkarni Feb 26, 2021


		Ray Serve logs can be ingested by your favorite external logging agent. Ray logs from the current session are exported to the directory `/tmp/ray/session_latest/logs` and remain there until the next session starts.

		Here is a quick walkthrough of how to explore and filter your logs using `Loki <https://grafana.com/oss/loki/>`__.


		.. code-block:: bash

		INFO -- Some info! component=serve backend=my_backend replica=my_backend#krcwoa

[Serve] Add logger with backend and replica tags #14251

[Serve] Add logger with backend and replica tags #14251

Conversation

architkulkarni commented Feb 22, 2021 • edited by edoakes Loading

Why are these changes needed?

Related issue number

Checks

simon-mo commented Feb 22, 2021

architkulkarni commented Feb 22, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

simon-mo commented Feb 23, 2021

simon-mo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

architkulkarni commented Feb 25, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

architkulkarni commented Feb 22, 2021 •

edited by edoakes

Loading