Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Only log hearbeat if status changed #529

Merged
merged 1 commit into from
Aug 18, 2024
Merged

Conversation

arp242
Copy link
Contributor

@arp242 arp242 commented Aug 14, 2024

Right now it will log this every five seconds, which really clobbers my terminal/logs, mostly with fairly useless debug messages:

 15:27 INFO  producer: Heartbeat
	     num_completed_jobs = 0
	     num_jobs_running   = 0
	     queue              = default
 15:27 INFO  producer: Heartbeat
	     num_completed_jobs = 0
	     num_jobs_running   = 0
	     queue              = default
 15:27 INFO  producer: Heartbeat
	     num_completed_jobs = 0
	     num_jobs_running   = 0
	     queue              = default
 15:27 INFO  producer: Heartbeat
	     num_completed_jobs = 0
	     num_jobs_running   = 0
	     queue              = default

I originally considered changing the InfoContext() to DebugContext(), but doing an Info log only if the status changed seemed like a good middle ground.

Copy link
Contributor

@brandur brandur left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Left a couple comments, but WFM.

producer.go Outdated Show resolved Hide resolved
producer.go Outdated Show resolved Hide resolved
producer.go Outdated Show resolved Hide resolved
@ccoVeille
Copy link

I like your changes, but I would like to suggest something.

The heartbeat could be logged on each call with debug level, and the state change is logged with info level.

It would help a lot when a debug is needed.

I'm a bit afraid no log at all could lead to problem

producer.go Outdated Show resolved Hide resolved
@arp242
Copy link
Contributor Author

arp242 commented Aug 18, 2024

I'm a bit afraid no log at all could lead to problem

@ccoVeille I don't think this will actually log less information? It just won't log if the message will be identical (because none of the log parameters changed).

@ccoVeille
Copy link

heartbeat will be silent if nothing changed.

That's what your PR is about.

But won't it log nothing for hours if nothing changed. Or maybe I missed something in the conditions.

What will affect the count?

@brandur
Copy link
Contributor

brandur commented Aug 18, 2024

@ccoVeille So I think the idea is that while yes, nothing gets logged if nothing is changing, this might be a reasonable compromise for most systems. i.e. Any systems were any jobs are moving through queues at all, you'll see logging basically the same as you did before. But for systems where nothing is happening (like in say dev), we bias towards quieter log outputs.

This seems to make sense to me, although I can imagine an alternative where we should make it a Debug line and the client gets even quieter, and those who want a higher output client can either use debug level, or attach their own hooks into the even system.

Thoughts?

producer.go Outdated Show resolved Hide resolved
Right now it will log this every five seconds, which really clobbers my
terminal/logs, mostly with fairly useless debug messages:

	 15:27 INFO  producer: Heartbeat
		     num_completed_jobs = 0
		     num_jobs_running   = 0
		     queue              = default
	 15:27 INFO  producer: Heartbeat
		     num_completed_jobs = 0
		     num_jobs_running   = 0
		     queue              = default
	 15:27 INFO  producer: Heartbeat
		     num_completed_jobs = 0
		     num_jobs_running   = 0
		     queue              = default
	 15:27 INFO  producer: Heartbeat
		     num_completed_jobs = 0
		     num_jobs_running   = 0
		     queue              = default

I originally considered changing the InfoContext() to DebugContext(),
but doing an Info log only if the status changed seemed like a good
middle ground.
@brandur
Copy link
Contributor

brandur commented Aug 18, 2024

Thanks!

@brandur brandur merged commit 25bfd99 into riverqueue:master Aug 18, 2024
11 checks passed
@arp242 arp242 deleted the hbeat-log branch August 18, 2024 23:33
@ccoVeille
Copy link

I'm fine and agree with what you said.

I might open a PR with what I was thinking about. But my initial comment was a suggestion while the changes involved in the PR were already great.

So no worries

tigrato pushed a commit to gravitational/river that referenced this pull request Dec 18, 2024
Right now it will log this every five seconds, which really clobbers my
terminal/logs, mostly with fairly useless debug messages:

	 15:27 INFO  producer: Heartbeat
		     num_completed_jobs = 0
		     num_jobs_running   = 0
		     queue              = default
	 15:27 INFO  producer: Heartbeat
		     num_completed_jobs = 0
		     num_jobs_running   = 0
		     queue              = default
	 15:27 INFO  producer: Heartbeat
		     num_completed_jobs = 0
		     num_jobs_running   = 0
		     queue              = default
	 15:27 INFO  producer: Heartbeat
		     num_completed_jobs = 0
		     num_jobs_running   = 0
		     queue              = default

I originally considered changing the InfoContext() to DebugContext(),
but doing an Info log only if the status changed seemed like a good
middle ground.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants