[Log] make glog flush and RAY_LOG thread-safe #11002

ashione · 2020-09-24T13:59:27Z

Current RAY_LOG will make duplicated output in log files.
For example, all logs of RAY_LOG(ERROR) will be flushed three times to destination file since we use a same sink file for INFO, WARN and ERROR level.

More important thing is this implementation is not thread-safe, so we'd better use glog default logobject.

Why are these changes needed?

Related issue number

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 :(

ashione · 2020-09-24T14:12:06Z

It's runnning as same as previous version in my laptop. @mehrdadn Could you double check the log destination file and directory? We'd better make the proper log files end up in the proper folder. (also works well Windows)

kfstorm

AFAIK, GLOG has already done locking here, so we don't need to worry about thread-safety in custom loggers.

src/ray/util/logging.cc

thirdparty/patches/glog-suffix-log.patch

ashione · 2020-09-24T17:41:51Z

AFAIK, GLOG has already done locking here, so we don't need to worry about thread-safety in custom loggers.

Glog guarantees base logger thread safe by holding muted lock inside. But we cannot assert it works well definitely. For example, other thread is logging somethings to destination file when stream logger singleton has been closed in ShutdownRayLog before invoking glog shutdown.

kfstorm · 2020-09-24T18:09:43Z

I agree that ShutdownRayLog is not thread-safe.

…

On Sep 25, 2020, 01:42 +0800, Lingxuan Zuo ***@***.***>, wrote: > AFAIK, GLOG has already done locking here, so we don't need to worry about thread-safety in custom loggers. Glog guarante base logger thread safe by holding muted lock inside. But we cannot assert it works well definitely. For example, other thread is logging somethings to destination file when stream logger singleton has been closed in ShutdownRayLog before invoking glog shutdown. — You are receiving this because your review was requested. Reply to this email directly, view it on GitHub, or unsubscribe.

ashione · 2020-09-25T06:09:20Z

@kfstorm @rkooo567 @mehrdadn Any comments about this PR? Streaming ci failure in travis will be unrelated with this.

kfstorm

Please wait for @mehrdadn's comments since you are trying to remove StreamLogger.

thirdparty/patches/glog-suffix-log.patch

kfstorm · 2020-09-25T06:19:12Z

@mehrdadn Could you explain the motivation of replacing the default logger with StreamLogger?

mehrdadn · 2020-09-25T06:22:25Z

@kfstorm It was just to combine messages of different severities into the same log files (#9230), because my previous changes had resulted in them going into separate log files. The previous changes were trying to make sure that the log files were in the correct log directory (because in some cases logs used to be created in the wrong folder).

mehrdadn

@ashione To be honest glog was quite a headache for me to figure out and I only touched it incidentally (and at this point I've forgotten some details already). Also, I've actually stopped working on Ray. You might want to reach out to others for reviewing haha.

ashione · 2020-09-25T06:39:41Z

@ashione To be honest glog was quite a headache for me to figure out and I only touched it incidentally (and at this point I've forgotten some details already). Also, I've actually stopped working on Ray. You might want to reach out to others for reviewing haha.

Sorry to hear that. But thanks a lot for your response.

ashione · 2020-09-25T06:45:38Z

I find these comments in glog/logging.cc

 // If no base filename for logs of this severity has been set, use a
      // default base filename of
      // "<program name>.<hostname>.<user name>.log.<severity level>.".  So
      // logfiles will have names like
      // webserver.examplehost.root.log.INFO.19990817-150000.4354, where
      // 19990817 is a date (1999 August 17), 150000 is a time (15:00:00),
      // and 4354 is the pid of the logging process.  The date & time reflect
      // when the file was created for output.
      //
      // Where does the file get put?  Successively try the directories
      // "/tmp", and "."

So raylet's log will be printed in /tmp with ...log.. format.
@kfstorm

kfstorm · 2020-09-25T07:03:55Z

@ashione I see. So to fix the wrong log folder issue, can we just apply a patch to the GLOG source code to disable the "default base filename" feature? Then we can revert logging.cc to the version several months ago.

kfstorm · 2020-09-25T07:08:08Z

I must say that the logging to "/tmp" by default behavior is a really bad design. And it even can't be turned off. 🤷‍♂️

kfstorm · 2020-09-25T07:14:21Z

I find these comments in glog/logging.cc

 // If no base filename for logs of this severity has been set, use a
      // default base filename of
      // "<program name>.<hostname>.<user name>.log.<severity level>.".  So
      // logfiles will have names like
      // webserver.examplehost.root.log.INFO.19990817-150000.4354, where
      // 19990817 is a date (1999 August 17), 150000 is a time (15:00:00),
      // and 4354 is the pid of the logging process.  The date & time reflect
      // when the file was created for output.
      //
      // Where does the file get put?  Successively try the directories
      // "/tmp", and "."

So raylet's log will be printed in /tmp with ...log.. format.
@kfstorm

@mehrdadn is this "in some cases logs used to be created in the wrong folder" you met earlier?

mehrdadn · 2020-09-25T08:30:54Z

@kfstorm Yeah I meant that's what it was like prior to PR #9025, where I first tried to fix it.

ashione · 2020-09-25T09:15:57Z

I find these comments in glog/logging.cc

 // If no base filename for logs of this severity has been set, use a
      // default base filename of
      // "<program name>.<hostname>.<user name>.log.<severity level>.".  So
      // logfiles will have names like
      // webserver.examplehost.root.log.INFO.19990817-150000.4354, where
      // 19990817 is a date (1999 August 17), 150000 is a time (15:00:00),
      // and 4354 is the pid of the logging process.  The date & time reflect
      // when the file was created for output.
      //
      // Where does the file get put?  Successively try the directories
      // "/tmp", and "."

So raylet's log will be printed in /tmp with ...log.. format.
@kfstorm

@mehrdadn is this "in some cases logs used to be created in the wrong folder" you met earlier?

It's only extra log file on linux machine. Finally I fix it by mapping all severities to destination.

mehrdadn · 2020-09-25T10:22:24Z

By the way, not sure if this is relevant to what you're doing, but here's a repro I had for an issue where different severities would end up in different log files (and it explains why I used StreamLogger)... might be helpful to read: #9063 (comment)

ashione · 2020-09-25T10:38:23Z

By the way, not sure if this is relevant to what you're doing, but here's a repro I had for an issue where different severities would end up in different log files (and it explains why I used StreamLogger)... might be helpful to read: #9063 (comment)

Just set up all other levels of logging to empty destination. So there should be no such log files left by now.

ashione · 2020-09-25T10:45:53Z

But none of logging items can be redirected to raylet.out. Glog will print all of logs in stderr.

ashione · 2020-09-27T01:51:28Z

Also, I tested locally, and there are several issues.

Seems like raylet logs are not properly flushed.

Seems like there's weird file name for core worker (pid 010000).

I can't open the second snapshot figure. Could you upload it again?

ashione · 2020-09-27T01:53:24Z

@ashione I doubt the weird pid is unrelated to this PR because I cannot find it when I run the same code in other branch. Can you also try
import ray
ray.init()
import time
time.sleep(100)
for this branch & nightly, and see if both do or don't have that weird pid file?
Perphas it does not stand for PID. I find it in code of core_worker.cc

ray/src/ray/core_worker/core_worker.cc

Line 98 in b5ecdd0

app_name << "-" << global_worker_id_;

.
So that's 4 bytes jobid.

ashione · 2020-09-27T03:24:31Z

@rkooo567 A new pytest case for checking raylet.out/raylet.err has been added.

src/ray/util/logging.cc

kfstorm

We'd better check for worker logs as well.

python/ray/tests/test_raylet_output.py

kfstorm · 2020-09-27T13:56:51Z

python/ray/tests/test_raylet_output.py

+ # Make subprocess happy in bazel.
+ os.environ["LC_ALL"] = "en_US.UTF-8"
+ os.environ["LANG"] = "en_US.UTF-8"


Why we need these? I can't find them in

ray/python/ray/tests/test_advanced.py

Lines 512 to 514 in b5ecdd0

if __name__ == "__main__":

import pytest

sys.exit(pytest.main(["-v", __file__]))

I think this is needed for ray_start_regular (because of some click dependency issues)

I just paste them from test_ouput.py.

rkooo567 · 2020-09-27T17:22:57Z

Seems like there are memory corruption (look at asan test) and lint failure!

Once you resolved these, I will test locally again and approve!

ashione · 2020-09-28T01:54:54Z

Seems like there are memory corruption (look at asan test) and lint failure!

Once you resolved these, I will test locally again and approve!

It's fixed in latest commit.

src/ray/util/logging.cc

rkooo567

Let me test locally one last time before we merge.

rkooo567 · 2020-09-28T02:56:24Z

Btw, this is a really nice fix :). I always wondered why we have multiple Error logs haha

ashione · 2020-09-28T03:18:22Z

Btw, this is a really nice fix :). I always wondered why we have multiple Error logs haha

Because INFO and more high level logs will be written to info-log-file, and WARN and its more higher level also could be printed in warn-log-file, warn-logs have been recorded twice when info-log-file and warn-log-file are same destination.

rkooo567 · 2020-09-28T04:15:00Z

Okay. Confirm it looks great :)

rkooo567 · 2020-09-28T04:15:18Z

Please add the test_ok tag when it is ready to be merged.

ashione · 2020-09-28T09:50:06Z

I'll check travis failures.

ashione · 2020-09-28T13:36:47Z

@kfstorm @rkooo567 Could you merge it?

make glog flush and RAY_LOG thread-safe

9b5fd93

ashione requested review from mehrdadn, kfstorm, raulchen, rkooo567 and ericl September 24, 2020 13:59

kfstorm reviewed Sep 24, 2020

View reviewed changes

src/ray/util/logging.cc Show resolved Hide resolved

kfstorm reviewed Sep 24, 2020

View reviewed changes

thirdparty/patches/glog-suffix-log.patch Show resolved Hide resolved

dump error log to console

9da5628

rkooo567 self-assigned this Sep 24, 2020

rkooo567 changed the title ~~make glog flush and RAY_LOG thread-safe~~ [Log] make glog flush and RAY_LOG thread-safe Sep 24, 2020

kfstorm reviewed Sep 25, 2020

View reviewed changes

thirdparty/patches/glog-suffix-log.patch Show resolved Hide resolved

mehrdadn reviewed Sep 25, 2020

View reviewed changes

mapping all levels to destination

d95e7a4

ashione added 2 commits September 27, 2020 10:55

use stdout logger by default

f37451d

add raylet std/err pytest checker

e25f350

kfstorm reviewed Sep 27, 2020

View reviewed changes

src/ray/util/logging.cc Outdated Show resolved Hide resolved

kfstorm reviewed Sep 27, 2020

View reviewed changes

python/ray/tests/test_raylet_output.py Outdated Show resolved Hide resolved

python/ray/tests/test_raylet_output.py Outdated Show resolved Hide resolved

add worker logs file check

885be2b

kfstorm reviewed Sep 27, 2020

View reviewed changes

fix asan check

86847c2

kfstorm reviewed Sep 28, 2020

View reviewed changes

src/ray/util/logging.cc Outdated Show resolved Hide resolved

loop in glog enums

f447a28

kfstorm approved these changes Sep 28, 2020

View reviewed changes

rkooo567 approved these changes Sep 28, 2020

View reviewed changes

ashione added 3 commits September 28, 2020 14:10

fix python lint

8aaec7b

lint for autoindent

bb02f52

fix indent lint

4624574

ashione added the tests-ok The tagger certifies test failures are unrelated and assumes personal liability. label Sep 28, 2020

make raylet.err is not empty

d91d8a2

kfstorm merged commit 27e1f51 into ray-project:master Sep 28, 2020

kfstorm deleted the fix-unsafe-glog branch September 29, 2020 04:25

	if __name__ == "__main__":
	import pytest
	sys.exit(pytest.main(["-v", __file__]))

[Log] make glog flush and RAY_LOG thread-safe #11002

[Log] make glog flush and RAY_LOG thread-safe #11002

Conversation

ashione commented Sep 24, 2020

Why are these changes needed?

Related issue number

Checks

ashione commented Sep 24, 2020 • edited Loading

kfstorm left a comment

Choose a reason for hiding this comment

ashione commented Sep 24, 2020 • edited Loading

kfstorm commented Sep 24, 2020 via email

ashione commented Sep 25, 2020

kfstorm left a comment

Choose a reason for hiding this comment

kfstorm commented Sep 25, 2020

mehrdadn commented Sep 25, 2020

mehrdadn left a comment • edited Loading

Choose a reason for hiding this comment

ashione commented Sep 25, 2020

ashione commented Sep 25, 2020

kfstorm commented Sep 25, 2020

kfstorm commented Sep 25, 2020

kfstorm commented Sep 25, 2020

mehrdadn commented Sep 25, 2020

ashione commented Sep 25, 2020

mehrdadn commented Sep 25, 2020

ashione commented Sep 25, 2020

ashione commented Sep 25, 2020

ashione commented Sep 27, 2020

ashione commented Sep 27, 2020

ashione commented Sep 27, 2020

kfstorm left a comment

Choose a reason for hiding this comment

kfstorm Sep 27, 2020

Choose a reason for hiding this comment

rkooo567 Sep 27, 2020

Choose a reason for hiding this comment

ashione Sep 28, 2020

Choose a reason for hiding this comment

rkooo567 commented Sep 27, 2020 • edited Loading

ashione commented Sep 28, 2020

rkooo567 left a comment

Choose a reason for hiding this comment

rkooo567 commented Sep 28, 2020 • edited Loading

ashione commented Sep 28, 2020

rkooo567 commented Sep 28, 2020

rkooo567 commented Sep 28, 2020

ashione commented Sep 28, 2020

ashione commented Sep 28, 2020

ashione commented Sep 24, 2020 •

edited

Loading

ashione commented Sep 24, 2020 •

edited

Loading

mehrdadn left a comment •

edited

Loading

rkooo567 commented Sep 27, 2020 •

edited

Loading

rkooo567 commented Sep 28, 2020 •

edited

Loading