Adding logs to Tron to indicate start and scheduling times - TRON-2152 #948

EmanElsaban · 2024-04-03T20:02:35Z

This PR is for the tickets: TRON-2153 and TRON-2152

nemacysts

ty for adding more comments for how things work!

the bulk of my comments are generally just tweaking wording (and can be ignored if you'd like) - there's only a couple that we should definitely dig into (e.g., logging when the first k8s schedule happens as well as some of the time logs for functions that get called both for startup as well as for new config deployment)

bin/trond

tron/trondaemon.py

tron/mcp.py

nemacysts · 2024-04-03T20:36:57Z

tron/core/actionrun.py

@@ -1134,6 +1135,8 @@ def handle_action_command_state_change(self, action_command, event, event_data=N
 class KubernetesActionRun(ActionRun, Observer):
    """An ActionRun that executes the command on a Kubernetes cluster."""

+    start_schedule_jobs = True


I'm a little iffy on adding a boolean here - can we maybe add something to where we initialize the task_proc client instead?

tron/core/job_collection.py

nemacysts · 2024-04-04T19:46:55Z

tron/kubernetes.py

+        # This flag will be used to indicate in logs the first task we start scheduling and running on Kubernetes
+        self.start_schedule_jobs = start_schedule_jobs


i think we can probably skip this logic and say that we can start scheduling jobs after self.connect() has been called further below :)

hmm i wonder if we should add that log message after self.connect to indicate that we connected to task_proc and to also keep the current log produced after the flag "start_schedule_jobs". Because we do all the connection stuff under self._run_mcp(boot_time=boot_time) meanwhile we actually start submitting tasks to k8s when we are waiting after we run the reactor, at this point in the code

while True: signum = signal.sigwait(list(signal_map.keys()))

the log message from the start_schedule_jobs flag will probably be somewhat unreliable if we succeed in lowering the restart time as it will depend on job schedules

that said: the task_proc stuff does not run on the twisted reactor, so it should be possible for it to run beforehand

(although, I guess that until the reactor is running there won't be any new tasks submitted to task_proc)

in general, i'm a little hesitant to add a state-indicating boolean just for logging purposes, so perhaps we can try to use the tron/trondaemon.py logging as a proxy timing metric instead?

Actually, they both happen after the reactor runs under submit_command function. I wonder if we should still keep both though cause there are some function calls between them (i.e time spent in other functions)

nemacysts · 2024-04-04T19:48:34Z

tron/mcp.py

-        self.boot_time = time.time()
-        log.info("initialized")
+        self.boot_time = boot_time
+        current_time = time.strftime("%a, %d %b %Y %H:%M:%S", time.localtime(boot_time))


just double-checking: is time.localtime(None) valid?

yup, it prints

2024-04-05 05:03:11,461 tron.trondaemon INFO Starting setup processes... 2024-04-05 05:03:19,723 tron.mcp INFO Initialized. Tron started on Fri, 05 Apr 2024 05:03:16!

I think if we don't pass anything to localtime() or pass None , it converts the current time instead

nemacysts · 2024-04-04T19:50:52Z

tron/mcp.py

        states = self.state_watcher.restore(self.jobs.get_names())
        MesosClusterRepository.restore_state(states.get("mesos_state", {}))

-        self.jobs.restore_state(states.get("job_state", {}), action_runner)
+        self.jobs.restore_state(states.get("job_state", {}), action_runner, boot_time=self.boot_time)


on a second look through this diff: do we need to pass through boot_time here?

could we print the same log statement after restore_state() has been called here (or right before)?

it would result in a smaller, more targeted diff :)

nemacysts

generally lgtm - i can ship once we resolve the optional boot_time comment

(the other two are stylistic nits)

nemacysts · 2024-04-05T19:39:37Z

tron/mcp.py

        states = self.state_watcher.restore(self.jobs.get_names())
        MesosClusterRepository.restore_state(states.get("mesos_state", {}))
-
+        log.info(
+            f"Tron will start restoring state for the jobs and will start scheduling them! Time elapsed since Tron started {time.time()- self.boot_time}"


huh, i just moved this to my landscape-oriented monitor and noticed that black didn't format the f-string

Suggested change

f"Tron will start restoring state for the jobs and will start scheduling them! Time elapsed since Tron started {time.time()- self.boot_time}"

f"Tron will start restoring state for the jobs and will start scheduling them! Time elapsed since Tron started {time.time() - self.boot_time}"

nemacysts · 2024-04-05T19:39:50Z

tron/mcp.py

        self.jobs.restore_state(states.get("job_state", {}), action_runner)
+        log.info(
+            f"Tron completed restoring state for the jobs. Time elapsed since Tron started {time.time()- self.boot_time}"


same nit as above

Suggested change

f"Tron completed restoring state for the jobs. Time elapsed since Tron started {time.time()- self.boot_time}"

f"Tron completed restoring state for the jobs. Time elapsed since Tron started {time.time() - self.boot_time}"

nemacysts · 2024-04-05T19:42:59Z

tron/trondaemon.py

@@ -75,7 +75,7 @@ def __init__(self, options):
        self.signals = {signal.SIGINT: signal.default_int_handler}
        self.manhole_sock = f"{self.options.working_dir}/manhole.sock"

-    def run(self):
+    def run(self, boot_time=None):


(chatting about this internally: but on closer inspection, i think we want to make sure that this is set or add some guard clauses to the log statements below - otherwise, we're leaving a bit of a footgun around)

nemacysts · 2024-04-08T14:23:38Z

tron/serialize/runstate/dynamodb_state_store.py

@@ -136,7 +136,7 @@ def _consume_save_queue(self):
                log.error(error)
                with self.save_lock:
                    self.save_queue[key] = val
-        duration = time.time() - start


was this intentional?

nopee, will commit the past version

EmanElsaban requested review from nemacysts and KaspariK April 3, 2024 20:05

nemacysts reviewed Apr 3, 2024

View reviewed changes

Adding logs to Tron to indicate start and scheduling times

0999dbe

EmanElsaban force-pushed the u/emanelsabban/TRON-2153-and-TRON-2152 branch from b6e4761 to 0999dbe Compare April 4, 2024 12:24

Addressed reviews on the PR

b427e14

EmanElsaban requested a review from nemacysts April 4, 2024 19:13

nemacysts reviewed Apr 4, 2024

View reviewed changes

EmanElsaban added 2 commits April 5, 2024 09:18

Address reviews 2.0

be8dd2f

Deleting the start_schedule_jobs flag

17df30c

EmanElsaban requested a review from nemacysts April 5, 2024 18:52

nemacysts reviewed Apr 5, 2024

View reviewed changes

Making boot_time a required param

bc3ad87

EmanElsaban requested a review from nemacysts April 5, 2024 21:03

nemacysts reviewed Apr 8, 2024

View reviewed changes

bring back time.time in duration

e867044

EmanElsaban requested a review from nemacysts April 8, 2024 18:00

nemacysts approved these changes Apr 8, 2024

View reviewed changes

EmanElsaban merged commit 44e71db into master Apr 8, 2024
3 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adding logs to Tron to indicate start and scheduling times - TRON-2152 #948

Adding logs to Tron to indicate start and scheduling times - TRON-2152 #948

EmanElsaban commented Apr 3, 2024

nemacysts left a comment

nemacysts Apr 3, 2024

nemacysts Apr 4, 2024

EmanElsaban Apr 5, 2024

nemacysts Apr 5, 2024

nemacysts Apr 5, 2024

EmanElsaban Apr 5, 2024

nemacysts Apr 4, 2024

EmanElsaban Apr 5, 2024 •

edited

Loading

EmanElsaban Apr 5, 2024

nemacysts Apr 4, 2024

nemacysts left a comment

nemacysts Apr 5, 2024

nemacysts Apr 5, 2024

nemacysts Apr 5, 2024

nemacysts Apr 8, 2024

EmanElsaban Apr 8, 2024

		# This flag will be used to indicate in logs the first task we start scheduling and running on Kubernetes
		self.start_schedule_jobs = start_schedule_jobs

	f"Tron will start restoring state for the jobs and will start scheduling them! Time elapsed since Tron started {time.time()- self.boot_time}"
	f"Tron will start restoring state for the jobs and will start scheduling them! Time elapsed since Tron started {time.time() - self.boot_time}"

	f"Tron completed restoring state for the jobs. Time elapsed since Tron started {time.time()- self.boot_time}"
	f"Tron completed restoring state for the jobs. Time elapsed since Tron started {time.time() - self.boot_time}"

Adding logs to Tron to indicate start and scheduling times - TRON-2152 #948

Adding logs to Tron to indicate start and scheduling times - TRON-2152 #948

Conversation

EmanElsaban commented Apr 3, 2024

nemacysts left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

EmanElsaban Apr 5, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nemacysts left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

EmanElsaban Apr 5, 2024 •

edited

Loading