UX: rework stdout error when ray fails to start #35378

mattip · 2023-05-16T07:23:55Z

Why are these changes needed?

When ray fails to start the dashboard, it prints out the last 20 lines of the dashboard.log file. Here is what it printed when I had a problem with grpcio ¹

2023-05-16 00:38:43,039	ERROR services.py:1197 -- Failed to start the dashboard , return code -11
2023-05-16 00:38:43,040	ERROR services.py:1222 -- Error should be written to 'dashboard.log' 
or 'dashboard.err'. We are printing the last 20 lines for you. See 
'https://docs.ray.io/en/master/ray-observability/ray-logging.html#logging-directory-structure'
to find where the log file is.
2023-05-16 00:38:43,040	ERROR services.py:1266 -- 
The last 20 lines of /tmp/ray/session_2023-05-16_00-38-41_610459_85992/logs/dashboard.log 
(it contains the error message from the dashboard): 
2023-05-16 00:38:42,899	WARNING head.py:255 -- `prometheus_client` not found, so metrics will not be exported.

2023-05-16 00:38:43,157	INFO worker.py:1625 -- Started a local Ray instance.
[2023-05-16 00:38:43,781 E 85992 85992] core_worker.cc:191: Failed to register worker 0100000
0ffffffffffffffffffffffffffffffffffffffffffffffff to Raylet. IOError: [RayletClient] Unable
to register worker with raylet. No such file or directory

There are a few UX tweaks that can be made to the message:

The log file was only 2 lines long, not 20, so the number is not helpful. It is repeated twice.
The first line was not printed
The code knows whether it printed 'dashboard.log' or 'dashboard.err', so no need to be indecisive.
The link is not needed, the file name is printed

Note that in my case the error was elsewhere, so perhaps this whole effort to print the dashboard.log should be a little less certain that the error is exactly here.

After this PR, the same error prints out

2023-05-16 10:04:17,920 ERROR services.py:1197 -- Failed to start the dashboard , return code -11
2023-05-16 10:04:17,920 ERROR services.py:1248 -- Error should be written to 'dashboard.log' We are
printing the last lines
2023-05-16 10:04:17,920 ERROR services.py:1268 -- 
The last 2 lines of /tmp/ray/session_2023-05-16_10-04-16_493412_122666/logs/dashboard.log (it may
contain an error message from the dashboard): 
2023-05-16 10:04:17,780 INFO head.py:135 -- Dashboard head grpc address: 0.0.0.0:4289
2023-05-16 10:04:17,782 WARNING head.py:255 -- `prometheus_client` not found, so metrics will not be
exported.
2023-05-16 10:04:18,038 INFO worker.py:1625 -- Started a local Ray instance.
[2023-05-16 10:04:18,662 E 122666 122666] core_worker.cc:191: Failed to register worker
01000000ffffffffffffffffffffffffffffffffffffffffffffffff to Raylet. IOError: [RayletClient] Unable
to register worker with raylet. No such file or directory

Related issue number

Checks

I've signed off every commit(by using the -s flag, i.e., git commit -s) in this PR.
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 added any new APIs to the API Reference. For example, if I added a
  method in Tune, I've added it in doc/source/tune/api/ under the
  corresponding .rst file.
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 :(

This appeared while updating the conda recipe for v2.4.0 in resync grpcio requirements conda-forge/ray-packages-feedstock#98, I am still searching for the root cause, probably related to the last line with a bogus worker number and an IOError ↩

xieus · 2023-05-25T16:36:58Z

@rkooo567 could you review this PR?

rkooo567 · 2023-06-01T23:10:38Z

python/ray/_private/services.py

@@ -1258,6 +1254,11 @@ def read_log(filename, lines_to_read):
                            "Ray github. "
                            "https://github.com/ray-project/ray/issues"
                        )
+                logger.error(
+                    "Error should be written to 'dashboard.log' "
+                    "We are printing the last lines"


can you keep the link to the log directory?

Suggested change

"We are printing the last lines"

"We are printing the last {len(lines)} lines"

Both the log directory and the number of lines is contained a few lines lower. I think it should only appear once:

The last 2 lines of /tmp/ray/session_2023-05-16_10-04-16_493412_122666/logs/dashboard.log (it may contain an error message from the dashboard):

rkooo567 · 2023-06-01T23:10:56Z

python/ray/_private/services.py

                lines = []
                with open(dashboard_log, "rb") as f:
                    with mmap.mmap(f.fileno(), 0, access=mmap.ACCESS_READ) as mm:
                        end = mm.size()
                        for _ in range(lines_to_read):
                            sep = mm.rfind(b"\n", 0, end - 1)
                            if sep == -1:
+                                if end > 1:
+                                    lines.append(mm[: end - 1].decode("utf-8"))


can you add a unit test for this. case?

The point is to add the first line, which was missing before this PR. Note that the line

2023-05-16 10:04:17,780 INFO head.py:135 -- Dashboard head grpc address: 0.0.0.0:4289

is missing. Where should I add a test: is there currently a test for this part of the code that I can add to?

stale · 2023-07-19T05:08:56Z

This pull request has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions.

If you'd like to keep this open, just leave any comment, and the stale label will be removed.

rkooo567 · 2023-07-19T12:20:57Z

@mattip is it ready to review again?

mattip · 2023-07-19T13:00:56Z

Yes, I am still waiting for guidance how to write a test. I would need to check the output of the worker when it starts up and cannot access the HEAD node.

stale · 2023-09-17T00:16:16Z

This pull request has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions.

If you'd like to keep this open, just leave any comment, and the stale label will be removed.

h-vetinari · 2023-10-13T03:38:40Z

It would be great if this could be merged (test or not); it would help debug a long-standing issue (#35383) where we're stuck on not knowing what's going wrong at all. Perhaps after debugging that issue, it'll be easier to write a test.

Signed-off-by: mattip <matti.picus@gmail.com>

mattip · 2023-10-13T06:10:06Z

I rebased off master, maybe it will help move the review forward

stale · 2023-12-15T06:59:44Z

This pull request has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions.

If you'd like to keep this open, just leave any comment, and the stale label will be removed.

mattip force-pushed the startup-error branch from a5fd467 to 384b6c3 Compare May 16, 2023 09:44

mattip mentioned this pull request May 16, 2023

[Core] Failing to start when using grpcio 1.51.3: "IOError: [RayletClient] Unable to register worker with raylet. No such file or directory" #35383

Closed

xieus requested a review from rkooo567 May 25, 2023 16:35

rkooo567 reviewed Jun 1, 2023

View reviewed changes

rkooo567 added the @author-action-required The PR author is responsible for the next step. Remove tag to send back to the reviewer. label Jun 1, 2023

stale bot added the stale The issue is stale. It will be closed within 7 days unless there are further conversation label Jul 19, 2023

rkooo567 removed the stale The issue is stale. It will be closed within 7 days unless there are further conversation label Jul 19, 2023

stale bot added the stale The issue is stale. It will be closed within 7 days unless there are further conversation label Sep 17, 2023

rework stdout error when ray fails to start

a722954

Signed-off-by: mattip <matti.picus@gmail.com>

mattip force-pushed the startup-error branch from 384b6c3 to a722954 Compare October 13, 2023 06:09

stale bot removed the stale The issue is stale. It will be closed within 7 days unless there are further conversation label Oct 13, 2023

stale bot added the stale The issue is stale. It will be closed within 7 days unless there are further conversation label Dec 15, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

UX: rework stdout error when ray fails to start #35378

UX: rework stdout error when ray fails to start #35378

mattip commented May 16, 2023 •

edited

Loading

xieus commented May 25, 2023

rkooo567 Jun 1, 2023

rkooo567 Jun 1, 2023

mattip Jun 2, 2023

rkooo567 Jun 1, 2023

mattip Jun 2, 2023

stale bot commented Jul 19, 2023

rkooo567 commented Jul 19, 2023

mattip commented Jul 19, 2023

stale bot commented Sep 17, 2023

h-vetinari commented Oct 13, 2023 •

edited

Loading

mattip commented Oct 13, 2023

stale bot commented Dec 15, 2023

	"We are printing the last lines"
	"We are printing the last {len(lines)} lines"

UX: rework stdout error when ray fails to start #35378

Are you sure you want to change the base?

UX: rework stdout error when ray fails to start #35378

Conversation

mattip commented May 16, 2023 • edited Loading

Why are these changes needed?

Related issue number

Checks

Footnotes

xieus commented May 25, 2023

rkooo567 Jun 1, 2023

Choose a reason for hiding this comment

rkooo567 Jun 1, 2023

Choose a reason for hiding this comment

mattip Jun 2, 2023

Choose a reason for hiding this comment

rkooo567 Jun 1, 2023

Choose a reason for hiding this comment

mattip Jun 2, 2023

Choose a reason for hiding this comment

stale bot commented Jul 19, 2023

rkooo567 commented Jul 19, 2023

mattip commented Jul 19, 2023

stale bot commented Sep 17, 2023

h-vetinari commented Oct 13, 2023 • edited Loading

mattip commented Oct 13, 2023

stale bot commented Dec 15, 2023

mattip commented May 16, 2023 •

edited

Loading

h-vetinari commented Oct 13, 2023 •

edited

Loading