Dumb question about print()

Ray Libraries (Data, Train, Tune, Serve) Ray Serve
1

Why doesn’t the print() statement display in the console in this code which is taken from Calling Deployments via HTTP and Python — Ray 1.12.0 ?

app = FastAPI()
ray.init(address="auto", namespace="serve")
serve.start(detached=True)

@serve.deployment(route_prefix="/hello")
@serve.ingress(app)
class PrintTest:
    @app.get("/")
    def root(self):
        print("Why is this print() statement not displaying?")
        return "Hello, world!"

PrintTest.deploy()

while True:
    time.sleep(2)

The browser at http://127.0.0.1:8000/hello/ displays:
"Hello, world!"

But, the print() statement doesn’t display on the console. Thanks

2

@Henry_Thornton not a dumb question at all, this looks like a bug! I filed an issue on github to track this and we will get a fix out for it: [serve] `print` inside of FastAPI deployment isn't streamed to the console · Issue #24689 · ray-project/ray · GitHub

In the meantime, you should be able to use logger = logging.getLogger("ray.serve") and logger.info instead of print as a workaround.

2 Likes
3

Phew, thought I was going nuts.

4

Hmmm actually I can’t reproduce it. I ran the script after

ray start --head

and hit it with curl command.

I did get

(ServeController pid=34757) INFO 2022-05-11 17:18:43,706 controller 34757 checkpoint_path.py:17 - Using RayInternalKVStore for controller checkpoint and recovery.
(ServeController pid=34757) INFO 2022-05-11 17:18:43,708 controller 34757 http_state.py:115 - Starting HTTP proxy with name 'SERVE_CONTROLLER_ACTOR:SERVE_PROXY_ACTOR-node:127.0.0.1-0' on node 'node:127.0.0.1-0' listening on '127.0.0.1:8000'
(ServeController pid=34757) INFO 2022-05-11 17:18:45,088 controller 34757 deployment_state.py:1217 - Adding 1 replicas to deployment 'PrintTest'.
(HTTPProxyActor pid=34761) INFO:     Started server process [34761]
(HTTPProxyActor pid=34761) INFO 2022-05-11 17:18:50,944 http_proxy 127.0.0.1 http_proxy.py:320 - GET /hello 200 15.4ms
(PrintTest pid=34764) Why is this print() statement not displaying?
(PrintTest pid=34764) INFO 2022-05-11 17:18:50,943 PrintTest PrintTest#OwVmpL replica.py:483 - HANDLE __call__ OK 11.6ms
5

Performed 2 initialization sequences. The first didn’t display the print() statement but the second did.

ray start --head
serve start
ray.init()

python print_test.py

2022-05-12 09:12:38,342 INFO api.py:615 -- Updating deployment 'PrintTest'. component=serve deployment=PrintTest
2022-05-12 09:12:42,419 INFO api.py:630 -- Deployment 'PrintTest' is ready at `http://127.0.0.1:8000/hello`. component=serve deployment=PrintTest

ray --head
ray.init()
serve.start()

python print_test.py

(ServeController pid=12404) 2022-05-12 09:17:53,424     INFO checkpoint_path.py:15 -- Using RayInternalKVStore for controller checkpoint and recovery.
(ServeController pid=12404) 2022-05-12 09:17:53,548     INFO http_state.py:106 -- Starting HTTP proxy with name 'SERVE_CONTROLLER_ACTOR:SERVE_PROXY_ACTOR-node:127.0.0.1-0' on node 'node:127.0.0.1-0' listening on '127.0.0.1:8000'
2022-05-12 09:17:56,647 INFO api.py:794 -- Started detached Serve instance in namespace 'serve'.
(HTTPProxyActor pid=10932) INFO:     Started server process [10932]
2022-05-12 09:17:56,680 INFO api.py:615 -- Updating deployment 'PrintTest'. component=serve deployment=PrintTest
(ServeController pid=12404) 2022-05-12 09:17:56,792     INFO deployment_state.py:1210 -- Adding 1 replicas to deployment 'PrintTest'. component=serve deployment=PrintTest
2022-05-12 09:18:00,739 INFO api.py:630 -- Deployment 'PrintTest' is ready at `http://127.0.0.1:8000/hello`. component=serve deployment=PrintTest
(PrintTest pid=13148) Why is this print() statement not displaying?

Got there. But, wonder why the sequencing of serve affects the print() statement?

6

Ray 1.12, Windows 10

raystart.py:
subprocess.run(["ray", "start", "--head", "--port", "8787", "--num-cpus", "2", "--dashboard-host", "localhost", "--dashboard-port", "8265"], capture_output=True, text=True, shell=True)

main.py:

ray.init(address="127.0.0.1:8787", namespace="serve")
serve.start()

This works as it should perfectly.

7

Btw, using http_options in serve.start() fails:

raystart.py:
subprocess.run(["ray", "start", "--head", "--port", "8787", "--num-cpus", "2", "--dashboard-host", "localhost", "--dashboard-port", "8265"], capture_output=True, text=True, shell=True)

main.py:

http_options = {}
http_options["host"] = "127.0.0.1"
http_options["port"] = 8787
http_options["location"] = "HeadOnly"
http_options["num_cpus"] = 2

ray.init(address="127.0.0.1:8787", namespace="serve")
serve.start(http_options=http_options)

ray::HTTPProxyActor.ready() (pid=13332, ip=127.0.0.1, repr=<ray.serve.http_proxy.HTTPProxyActor object at 0x00000200B5906FA0>)
  File "python\ray\_raylet.pyx", line 656, in ray._raylet.execute_task
  File "python\ray\_raylet.pyx", line 697, in ray._raylet.execute_task
  File "python\ray\_raylet.pyx", line 663, in ray._raylet.execute_task
  File "python\ray\_raylet.pyx", line 667, in ray._raylet.execute_task
  File "python\ray\_raylet.pyx", line 609, in ray._raylet.execute_task.function_executor
  File "python\ray\_raylet.pyx", line 2130, in ray._raylet.CoreWorker.run_async_func_in_event_loop
  File "C:\Users\User\AppData\Local\Programs\Python\Python39\lib\concurrent\futures\_base.py", line 439, in result
    return self.__get_result()
  File "C:\Users\User\AppData\Local\Programs\Python\Python39\lib\concurrent\futures\_base.py", line 391, in __get_result
    raise self._exception
  File "C:\Users\User\AppData\Local\Programs\Python\Python39\lib\site-packages\ray\util\tracing\tracing_helper.py", line 494, in _resume_span
    return await method(self, *_args, **_kwargs)
  File "C:\Users\User\AppData\Local\Programs\Python\Python39\lib\site-packages\ray\serve\http_proxy.py", line 353, in ready
    return await done_set.pop()
  File "C:\Users\User\AppData\Local\Programs\Python\Python39\lib\site-packages\ray\util\tracing\tracing_helper.py", line 494, in _resume_span
    return await method(self, *_args, **_kwargs)
  File "C:\Users\User\AppData\Local\Programs\Python\Python39\lib\site-packages\ray\serve\http_proxy.py", line 373, in run
    raise ValueError(
ValueError: Failed to bind Ray Serve HTTP proxy to '127.0.0.1:8787'.
Please make sure your http-host and http-port are specified correctly.
8

I think the general idea here is that the process that first started serve.start(detached=True) will have log streaming working properly.

The following cases will have log streaming:

  • no background cluster: python script.py and it just calls serve.start()
  • background cluster and but first starts serve: ray start ---head and then serve.start() in a separate script.
  • background cluster, ray.init() in one script, and serve.start in another. The serve.start one will have log streamed.

The following cases will not have log streaming:

  • ray start --head, serve start in the CLI command. All subsequent scripts that connects to the same cluster won’t be able to have log streaming because the CLI command started the serve processes.
  • ray start --head, in a script that does ray.init(address="auto") and then serve.start, then run the script again. The first script will have log streaming, while the second case will not have log streaming.

Sorry if this explanation is a bit confusion, and we are actively working on better story for aggregating and view logs regardless of the start order here.

9

Might have said this before but need:

A standard or recommended startup and shutdown sequence for a single machine and a cluster.

The above for both development and production.

And of course, auto reload :slight_smile: