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

Stop mill goroutine when logger is closed #80

Open
wants to merge 1 commit into
base: v2.0
Choose a base branch
from

Conversation

nmiyake
Copy link

@nmiyake nmiyake commented Mar 15, 2019

Fixes #56

@nmiyake nmiyake mentioned this pull request Mar 15, 2019
@natefinch
Copy link
Owner

Awesome, thank you.

@bmoylan
Copy link

bmoylan commented Aug 6, 2019

Hey @natefinch mind taking a look at this?

jdhenke pushed a commit to jdhenke/lumberjack that referenced this pull request Aug 6, 2019
Previously, each lumberjack logger starts its own mill goroutine the first time
that the logger writes to a file, and the goroutine is never stopped. The
project has an open pull request,
natefinch#80, to stop the goroutine when the
logger is closed. However, even with that design, each open logger will always
have a mill goroutine that is active (even if it is not performing work). It
also means that a logger will never be garbage-collected (and hence its file
will never be closed) unless it is explicitly closed. Furthemore, even if a
logger is explicitly closed, if Write is called on any references to that
logger, that will restart the persistent mill goroutine and reintroduce the
leaked file handle.

This change modifies the mill goroutine logic. It still maintains the overall
design of synchronously rotating and asynchronously deleting and compressing
(milling) the old, rotated log files, and that if a request to mill comes in
while one call is already happening, another mill will be executed after the
current one to ensure any newly rotated files are not missed. There is at most
one active mill goroutine which is in the process of performing a single pass
of deletions and compressions of rotated log files, and at most one queued mill
goroutine which is just waiting on a mutex. Now, each mill goroutine exits once
a single pass is done and future calls to mill will start a new goroutine (if
one is not already queued.)

This modification allows for lumberjack loggers to be garbage-collected, which
allows it to close file handles gracefully without an explicit call to "close".

The downside to this new approach is in the case where rotations are constantly
happening, rather than having a single goroutine simply process each mill pass,
a new goroutine must be started for each pass.

---

We have an internal fork of lumberjack that contains this change that we are
using in production.

An alternative approach was sketched after the fact that is not in use
internally but would have at most one mill goroutine per logger at any time,
rather than one active and one queued as in this approach. This alternative
design is shown here:

natefinch/lumberjack@v2.0...jdhenke:only-mill-as-needed
jdhenke pushed a commit to jdhenke/lumberjack that referenced this pull request Aug 6, 2019
Previously, each lumberjack logger starts its own mill goroutine the first time
that the logger writes to a file, and the goroutine is never stopped. The
project has an open pull request,
natefinch#80, to stop the goroutine when the
logger is closed. However, even with that design, each open logger will always
have a mill goroutine that is active (even if it is not performing work). It
also means that a logger will never be garbage-collected (and hence its file
will never be closed) unless it is explicitly closed. Furthemore, even if a
logger is explicitly closed, if Write is called on any references to that
logger, that will restart the persistent mill goroutine and reintroduce the
leaked file handle.

This change modifies the mill goroutine logic. It still maintains the overall
design of synchronously rotating and asynchronously deleting and compressing
(milling) the old, rotated log files, and that if a request to mill comes in
while one call is already happening, another mill will be executed after the
current one to ensure any newly rotated files are not missed. There is at most
one active mill goroutine which is in the process of performing a single pass
of deletions and compressions of rotated log files, and at most one queued mill
goroutine which is just waiting on a mutex. Now, each mill goroutine exits once
a single pass is done and future calls to mill will start a new goroutine (if
one is not already queued.)

This modification allows for lumberjack loggers to be garbage-collected, which
allows it to close file handles gracefully without an explicit call to "close".

The downside to this new approach is in the case where rotations are constantly
happening, rather than having a single goroutine simply process each mill pass,
a new goroutine must be started for each pass.

---

We have an internal fork of lumberjack that contains this change that we are
using in production.

An alternative approach was sketched after the fact that is not in use
internally but would have at most one mill goroutine per logger at any time,
rather than one active and one queued as in this approach. This alternative
design is shown here:

#2
jdhenke pushed a commit to jdhenke/lumberjack that referenced this pull request Aug 6, 2019
Previously, each lumberjack logger starts its own mill goroutine the first time
that the logger writes to a file, and the goroutine is never stopped. The
project has an open pull request,
natefinch#80, to stop the goroutine when the
logger is closed. However, even with that design, each open logger will always
have a mill goroutine that is active (even if it is not performing work). It
also means that a logger will never be garbage-collected (and hence its file
will never be closed) unless it is explicitly closed. Furthemore, even if a
logger is explicitly closed, if Write is called on any references to that
logger, that will restart the persistent mill goroutine and reintroduce the
leaked file handle.

This change modifies the mill goroutine logic. It still maintains the overall
design of synchronously rotating and asynchronously deleting and compressing
(milling) the old, rotated log files, and that if a request to mill comes in
while one call is already happening, another mill will be executed after the
current one to ensure any newly rotated files are not missed. There is at most
one active mill goroutine which is in the process of performing a single pass
of deletions and compressions of rotated log files, and at most one queued mill
goroutine which is just waiting on a mutex. Now, each mill goroutine exits once
a single pass is done and future calls to mill will start a new goroutine (if
one is not already queued.)

This modification allows for lumberjack loggers to be garbage-collected, which
allows it to close file handles gracefully without an explicit call to "close".

The downside to this new approach is in the case where rotations are constantly
happening, rather than having a single goroutine simply process each mill pass,
a new goroutine must be started for each pass.

---

We have an internal fork of lumberjack that contains this change that we are
using in production.

An alternative approach was sketched after the fact that is not in use
internally but would have at most one mill goroutine per logger at any time,
rather than one active and one queued as in this approach. This alternative
design is shown here:

#2
@howbazaar
Copy link

There is a problem of retrency here. The current behaviour of the Logger is that if Close is called, and you do another Write, the file is reopened, but the milling no longer works.

I proposed my own fix to this #100 before I realised there were a number of other PRs to address the issue. My final implementation uses a similar wait group approach to yours.

@abhi8086
Copy link

abhi8086 commented Oct 4, 2020

Hi @natefinch / team I am using lumberjack for one of our systems since last week and it's working great. However facing this issue from 3 days where goroutines are increasing continuously.

image

I believe it's related with this issue. Any suggestions on mitigating this issue.

current lumberjack goroutine count is 243.

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.

goroutine leak
5 participants