[RFC] Improved autoscaler log messages

[ericl]

The current autoscaler output is quite difficult to interpret due to its verbosity and low-level details. This is a proposal to clean it by periodically emitting the following summary table:

======== Autoscaler status 2020-11-20 23:14:36,653 ========
Node status
------------------------------------------------------------
Healthy:
 2 p3.2xlarge (2 active)
 20 m4.4xlarge (18 active, 2 idle)

Pending:
 34.5.234.51: m4.4xlarge, launching
 34.5.234.52: m4.4xlarge, launching
 34.5.234.53: m4.4xlarge, waiting for ssh
 34.5.234.54: m4.4xlarge, waiting for ssh
 34.5.234.55: m4.4xlarge, starting ray, /tmp/ray/setup-10.log
 34.5.234.56: m4.4xlarge, setting up, /tmp/ray/setup-11.log
 34.5.234.57: m4.4xlarge, setting up, /tmp/ray/setup-12.log

Recent failures:
 172.24.25.33: m4.4xlarge, /tmp/ray/setup-8.log
 35.4.235.11: p3.2xlarge, /tmp/ray/setup-9.log

Resources
------------------------------------------------------------
Usage:
 530.0/544.0 CPU
 2.0/2.0 GPU
 0.0/2.0 AcceleratorType:V100
 0.0 GiB/1583.19 GiB memory
 0.0 GiB/471.02 GiB object_store_memory

Demands:
 {"CPU": 1}: 150 pending tasks
 [{"CPU": 4} * 5]: 5 pending placement groups
 [{"CPU": 1} * 100]: from request_resources()

Implementation details:

• The autoscaler should periodically generate a JSON status message that includes the above information.
• We should log the above text summary for of the JSON status every 10-30s.
• Other ray components such as the dashboard and ray status can also access this information.

[richardliaw]

cc @mkoh-asapp @mattearllongshot

[ijrsvt]

@ericl Would it be useful to include something about the head_node in this output (like which one it is)?

[rkooo567]

cc @mfitton We should definitely port this to our dashboard.

[markgoodhead]

This would be a game-changing feature for autoscaler debugging/visibility - can't wait until this is on the dashboard!

[richardliaw]

cc @maximsmol this would be a good thing to use (especially since the plan is to emit json)

[wuisawesome]

Hmm now that we're adding these to ray status, I wonder if we should also make some of this information available programmatically... Just a thought.

[richardliaw]

yep! cc @maximsmol who is investigating a prototype

…

On Fri, Dec 11, 2020 at 12:38 PM Alex Wu ***@***.***> wrote: Hmm now that we're adding these to ray status, I wonder if we should also make some of this information available programmatically... Just a thought. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#12221 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABCRZZIMTUSUANODXN5LIP3SUJ7LRANCNFSM4T5MYIPQ> .

[edoakes]

FYI we are currently exposing this programmatically in the dashboard (/api/cluster_status), but it currently isn't advertised anywhere.

[AmeerHajAli]

@ericl @wuisawesome can we close this issue?

[wuisawesome]

I'd call it 95% done since we don't have the per-file logging doen yet

[DmitriGekhtman]

What remains to do is the per-node logging, and this task has been delegated to me.

Let me just confirm the requirement and a potential way to do it.

?Requirement?:
We need a log file for each node_id, and each NodeUpdater running inside of the monitor process should log to that file.

?Design?:
One strategy is to put the requisite logging logic in the NodeUpdater --
Give the NodeUpdater a self.logger attribute.
Have the NodeUpdater detect by some means if it's running inside the monitor process.
If it's not running in the monitor process, then
self.logger = logger, where logger is the logger = logging.getLogger(__name__) defined at the top of the file.
If it is running in the monitor process, then self.logger is a custom logger that doesn't belong to the standard logging hierarchy and writes to a node_id-dependent log file.

@rkooo567
Does this sound like a remotely sane strategy?

If anyone has a better idea, let me know.

[ericl]

I recall the node updater used to be a process, so you could redirect stdout to a file directly. It seems to be a thread now, so maybe we have to pass a logger and also capture any child command outputs as well. We could also try moving it back to a process but that sounds like a bigger change.

…

On Thu, Jan 14, 2021, 9:13 PM Dmitri Gekhtman ***@***.***> wrote: What remains to do is the per-node logging, and this task has been delegated to me. Let me just confirm the requirement and a potential way to do it. ?Requirement?: We need a log file for each node_id, and each NodeUpdater running inside of the monitor process should log to that file. ?Design?: One strategy is to put the requisite logging logic in the NodeUpdater -- Give the NodeUpdater a self.logger attribute. Have the NodeUpdater detect by some means if it's running inside the monitor process. If it's not running in the monitor process, then self.logger = logger, where logger is the logger = logging.getLogger(__name__) defined at the top of the file. If it is running in the monitor process, then self.logger is a custom logger that doesn't belong to the standard logging hierarchy and writes to a node_id-dependent log file. @rkooo567 <https://github.com/rkooo567> Does this sound like a remotely sane strategy? If anyone has a better idea, let me know. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#12221 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAADUSVZGHTNCSWKAWBUFELSZ7FIPANCNFSM4T5MYIPQ> .

[richardliaw]

@DmitriGekhtman

IIRC you shouldn't be using logging in NodeUpdater, but rather the custom autoscaler CLI logger. There should be an option for that logger to write stdout/stderr to a specific file upon invocation of command (at least for non-kubernetes environments such as Docker and standard).

This logger should be used in both cases of being in a monitor process or not (rather, the stdout redirect should be toggled).

[DmitriGekhtman]

@richardliaw Ah, yep you're right, it uses the CLI logger.
@ericl And yeah, need to figure out how to redirect child command output.

[DmitriGekhtman]

cli_logger.print just prints, as far as I can tell
https://github.com/ray-project/ray/blob/master/python/ray/autoscaler/_private/cli_logger.py#L422

[wuisawesome]

I'm not sure how you would go about using a logger here since iirc we don't capture any output. My assumption this would be done by redirecting stdout at the process runner level.

[DmitriGekhtman]

hmm, well, right now stdout and stderr go to monitor.out and monitor.err,
and monitor.log gets all log records at level >= info.

For the purposes of this issue, are the "autoscaler log messages" we're talking about the contents of monitor.log?

[DmitriGekhtman]

ech -- anyways, i see: the goal is to redirect all output of cmds run by NodeUpdater.cmd_runner to the relevant file.

[ericl]

fyi @clarkzinzow this might be a good starter issue

[DmitriGekhtman]

^ feel free to change the assignment from me to @clarkzinzow if Clark is interested
cc @AmeerHajAli

[wuisawesome]

Minor update: we should refer to failed nodes by their id, since ip addresses can be reused when failed nodes are terminated.

[ericl]

Hmm IDs aren't as useful though, about as useful as an out of date IP. If we keep failed nodes alive, then IPs should still be relevant right? So we should still keep the IPs since they're more generally useful.

…

On Wed, Feb 10, 2021, 5:21 PM Alex Wu ***@***.***> wrote: Minor update: we should refer to failed nodes by their id, since ip addresses can be reused when failed nodes are terminated. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#12221 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAADUSSLLNNWQVZXOMSKS3TS6MWHPANCNFSM4T5MYIPQ> .

[wuisawesome]

ok, we can use IP, but it puts us at the mercy of the k8s ip allocation policy.

[wuisawesome]

@yiranwang52 what should the /tmp/ray/setup-10.log part look like for the k8s operator?

[AmeerHajAli]

Closing this since the final piece here is covered in this issue: #13586