Revert "Global logging format changes" #34126

krfricke · 2023-04-06T04:44:54Z

Adter manual bisection, I think this PR may be causing the "Documentation" tests to fail.

The failure was previously masked by an actual failing doctest, but after this commit, actor outputs clutter the doctests and lead to mismatches in expected and actual output.

Let's see if reverting fixes these problems.

Reverts #32741

This reverts commit dc558d5.

rkooo567 · 2023-04-06T04:50:25Z

Cna you also comment which doc test has failed after merging this?

ArturNiederfahrenhorst · 2023-04-06T04:50:36Z

Whoops. Not from docs 🙂

krfricke · 2023-04-06T04:51:58Z

@rkooo567 it's 41 doctests, e.g. in this raw output

search for "Expected:"

I think most of them are related to datasets/DAG outputs printed from actors.

krfricke · 2023-04-06T04:53:21Z

Example:

File "data/getting-started.rst", line 175, in default

Failed example:

    batches = transformed_dataset.iter_batches(batch_size=8)

    print(next(iter(batches)))

Expected:

       sepal length (cm)  ...  target

    0                5.2  ...       1

    1                5.4  ...       1

    2                4.9  ...       2



    [3 rows x 5 columns]

Got:

    �[2;36m[06:39:25 PM]�[0m�[2;36m �[0m�[34mINFO    �[0m Executing DAG                    �]8;id=583159;file:///ray/python/ray/data/_internal/execution/streaming_executor.py�\�[2mstreaming_executor.py�[0m�]8;;�\�[2m:�[0m�]8;id=906406;file:///ray/python/ray/data/_internal/execution/streaming_executor.py#87�\�[2m87�[0m�]8;;�\

    �[2;36m              �[0m         InputDataBuffer�[1m[�[0mInput�[1m]�[0m ->        �[2m                        �[0m

    �[2;36m              �[0m         TaskPoolMapOperator�[1m[�[0mReadCSV->�[1;35mMap�[0m �[2m                        �[0m

    �[2;36m              �[0m         �[1;35mBatches�[0m�[1m(�[0mtransform_batch�[1m)�[0m�[1m]�[0m        �[2m                        �[0m

       sepal length (cm)  ...  target

    0                5.2  ...       1

    1                5.4  ...       1

    2                4.9  ...       2



    [3 rows x 5 columns]

richardliaw

cc @peytondmurray

rkooo567 · 2023-04-06T06:28:13Z

Hey guys. Plz do not merge this yet. This pr requires reviews from many teams, and it was pretty difficult to merge it, so i’d like to see if I can fix the doc test rather than reverting it doing the same thing. If I fail by EoD today, I will revert it.

peytondmurray · 2023-04-06T07:39:22Z

@rkooo567 In the specific example above, ray.data uses an object called a DatasetLogger which calls basicConfig() that targets a file for output (not stdout or stderr) the first time DatasetLogger.get_logger() is called; this is why we didn't see these messages before - they were being written to file.

IMO there is no bug here: these messages ought to be displayed to the user. For this particular case we can ignore the logging output in this doctest rather than revert the whole change. @rkooo567 Let's coordinate the fix here - I'm happy to work on this in the morning first thing if that works for you.

rkooo567 · 2023-04-06T11:02:19Z

@peytondmurray I see. So my guess is the right fix is the logger inside the DatasetLogger needs to have 2 handlers (stdout handler and file handler) instead of having the parent stdout_logger and we don't add a handler if log_to_driver = False. Is this correct? I agree the current behavior is the intended behavior of the logger.

Btw, do you have insight why after your PR, the behavior is changed? My gut feeling is this should have been the same before, but it seems like your PR somehow changes this behavior...

Also, yes. Can you take a look at the fix and make a PR asap? I blocked merging this for now, but we cannot delay this long. We should revert it if it is not fixed promptly...

rkooo567 · 2023-04-06T11:43:27Z

@peytondmurray #34131

I believe this should fix the issue? Can you take a look? Also feel free to push code directly or make your own PR if other approach is needed

rkooo567 · 2023-04-07T14:50:29Z

Okay. We failed to find the root cause so far (it looks like we can fix the getting-started failure, but there are other failures that are only happening when tests are run by make doctest). Since I don't want to break the master long time, I'd be okay to merge this PR. @peytondmurray I think we should recreate a PR and bisect features to find the root cause of this failure....

rkooo567 · 2023-04-07T22:39:02Z

cc @peytondmurray

rkooo567 · 2023-04-07T22:39:12Z

Let's create a new PR and try fixing this issue...

peytondmurray · 2023-04-07T22:44:40Z

@rkooo567 Yep. I'll make a new PR now so we can start working on it.

Adter manual bisection, I think this PR may be causing the "Documentation" tests to fail. The failure was previously masked by an actual failing doctest, but after this commit, actor outputs clutter the doctests and lead to mismatches in expected and actual output. Let's see if reverting fixes these problems. Reverts ray-project#32741 Signed-off-by: elliottower <[email protected]>

This reverts commit 45d5f65. Signed-off-by: pdmurray <[email protected]>

Adter manual bisection, I think this PR may be causing the "Documentation" tests to fail. The failure was previously masked by an actual failing doctest, but after this commit, actor outputs clutter the doctests and lead to mismatches in expected and actual output. Let's see if reverting fixes these problems. Reverts ray-project#32741 Signed-off-by: Jack He <[email protected]>

This reverts commit 45d5f65. Signed-off-by: pdmurray <[email protected]>

Attempts to consolidate logging configuration by introducing reasonable defaults in ray/log.py. This new logging configuration is done once in ray/__init__.py at the top of the module. Subsequent calls to the configuration are ignored. A logger for ray.rllib is configured at the WARN level, to address Revert "Simplify logging configuration. (#30863)" #31858. With this change, Revert "Simplify logging configuration. (#30863)" #31858 can be reverted, again simplifying and consolidating logging configuration. Modified test_output.py::test_logger_config to test only the logger config, not launch a ray cluster. The test was failing intermittently, I think due to a race condition between the launch of the cluster and the reading of the subprocess's stdout, and anyway it wasn't necessary to call ray.init here to check that logging was configured correctly. Modified python/ray/tune/tests/test_commands.py::test_ls_with_cfg to test the underlying data, not what gets printed to stdout (which has changed with the new logging system). Modified a logging message in ray.tune.automl.search_policy.AutoMLSearcher.on_trial_complete, which in certain cases emits a logging message which tries to format a NoneType into a %f during log message formatting. This was a previously-undetected bug which showed up because the default log level is now INFO. This fixes a test that was failing in test_automl_searcher.py::AutoMLSearcherTest.

…ay-project#34182) Attempts to consolidate logging configuration by introducing reasonable defaults in ray/log.py. This new logging configuration is done once in ray/__init__.py at the top of the module. Subsequent calls to the configuration are ignored. A logger for ray.rllib is configured at the WARN level, to address Revert "Simplify logging configuration. (ray-project#30863)" ray-project#31858. With this change, Revert "Simplify logging configuration. (ray-project#30863)" ray-project#31858 can be reverted, again simplifying and consolidating logging configuration. Modified test_output.py::test_logger_config to test only the logger config, not launch a ray cluster. The test was failing intermittently, I think due to a race condition between the launch of the cluster and the reading of the subprocess's stdout, and anyway it wasn't necessary to call ray.init here to check that logging was configured correctly. Modified python/ray/tune/tests/test_commands.py::test_ls_with_cfg to test the underlying data, not what gets printed to stdout (which has changed with the new logging system). Modified a logging message in ray.tune.automl.search_policy.AutoMLSearcher.on_trial_complete, which in certain cases emits a logging message which tries to format a NoneType into a %f during log message formatting. This was a previously-undetected bug which showed up because the default log level is now INFO. This fixes a test that was failing in test_automl_searcher.py::AutoMLSearcherTest.

…ay-project#34182) Attempts to consolidate logging configuration by introducing reasonable defaults in ray/log.py. This new logging configuration is done once in ray/__init__.py at the top of the module. Subsequent calls to the configuration are ignored. A logger for ray.rllib is configured at the WARN level, to address Revert "Simplify logging configuration. (ray-project#30863)" ray-project#31858. With this change, Revert "Simplify logging configuration. (ray-project#30863)" ray-project#31858 can be reverted, again simplifying and consolidating logging configuration. Modified test_output.py::test_logger_config to test only the logger config, not launch a ray cluster. The test was failing intermittently, I think due to a race condition between the launch of the cluster and the reading of the subprocess's stdout, and anyway it wasn't necessary to call ray.init here to check that logging was configured correctly. Modified python/ray/tune/tests/test_commands.py::test_ls_with_cfg to test the underlying data, not what gets printed to stdout (which has changed with the new logging system). Modified a logging message in ray.tune.automl.search_policy.AutoMLSearcher.on_trial_complete, which in certain cases emits a logging message which tries to format a NoneType into a %f during log message formatting. This was a previously-undetected bug which showed up because the default log level is now INFO. This fixes a test that was failing in test_automl_searcher.py::AutoMLSearcherTest. Signed-off-by: e428265 <[email protected]>

Revert "Global logging format changes (#32741)"

0598f6e

This reverts commit dc558d5.

krfricke requested a review from a team as a code owner April 6, 2023 04:44

ArturNiederfahrenhorst approved these changes Apr 6, 2023

View reviewed changes

richardliaw approved these changes Apr 6, 2023

View reviewed changes

rkooo567 added the do-not-merge Do not merge this PR! label Apr 6, 2023

maxpumperla approved these changes Apr 6, 2023

View reviewed changes

rkooo567 mentioned this pull request Apr 6, 2023

[WIP][Data] Fix the dataset logger to use the Python best practice. #34131

Closed

8 tasks

rkooo567 removed the do-not-merge Do not merge this PR! label Apr 7, 2023

rkooo567 merged commit 45d5f65 into master Apr 7, 2023

rkooo567 deleted the revert-32741-global-logging-config-format branch April 7, 2023 22:38

peytondmurray mentioned this pull request Apr 7, 2023

[WIP] Implement global logging configuration #34179

Closed

8 tasks

jianoaix mentioned this pull request Apr 7, 2023

[docs] docs build is failing #34064

Closed

peytondmurray added a commit to peytondmurray/ray that referenced this pull request Apr 25, 2023

Revert "Revert "Global logging format changes" (ray-project#34126)"

663d5e5

This reverts commit 45d5f65. Signed-off-by: pdmurray <[email protected]>

peytondmurray added a commit to peytondmurray/ray that referenced this pull request May 18, 2023

Revert "Revert "Global logging format changes" (ray-project#34126)"

8211f2e

This reverts commit 45d5f65. Signed-off-by: pdmurray <[email protected]>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Revert "Global logging format changes" #34126

Revert "Global logging format changes" #34126

krfricke commented Apr 6, 2023

rkooo567 commented Apr 6, 2023

ArturNiederfahrenhorst commented Apr 6, 2023

krfricke commented Apr 6, 2023 •

edited

Loading

krfricke commented Apr 6, 2023

richardliaw left a comment

rkooo567 commented Apr 6, 2023 •

edited

Loading

peytondmurray commented Apr 6, 2023 •

edited

Loading

rkooo567 commented Apr 6, 2023

rkooo567 commented Apr 6, 2023

rkooo567 commented Apr 7, 2023 •

edited

Loading

rkooo567 commented Apr 7, 2023

rkooo567 commented Apr 7, 2023

peytondmurray commented Apr 7, 2023

Revert "Global logging format changes" #34126

Revert "Global logging format changes" #34126

Conversation

krfricke commented Apr 6, 2023

rkooo567 commented Apr 6, 2023

ArturNiederfahrenhorst commented Apr 6, 2023

krfricke commented Apr 6, 2023 • edited Loading

krfricke commented Apr 6, 2023

richardliaw left a comment

Choose a reason for hiding this comment

rkooo567 commented Apr 6, 2023 • edited Loading

peytondmurray commented Apr 6, 2023 • edited Loading

rkooo567 commented Apr 6, 2023

rkooo567 commented Apr 6, 2023

rkooo567 commented Apr 7, 2023 • edited Loading

rkooo567 commented Apr 7, 2023

rkooo567 commented Apr 7, 2023

peytondmurray commented Apr 7, 2023

krfricke commented Apr 6, 2023 •

edited

Loading

rkooo567 commented Apr 6, 2023 •

edited

Loading

peytondmurray commented Apr 6, 2023 •

edited

Loading

rkooo567 commented Apr 7, 2023 •

edited

Loading