Added support for local files to --log-output
#2285
Conversation
|
|
There was a problem hiding this comment.
Hey @alyakimenko,
thanks for your contribution 🙏 🎉
Some request changes in the comments. Also, did you try to use the logrus' builtin writer?
Codecov Report
@@ Coverage Diff @@
## master #2285 +/- ##
==========================================
+ Coverage 72.71% 74.37% +1.65%
==========================================
Files 184 188 +4
Lines 14571 15230 +659
==========================================
+ Hits 10596 11328 +732
+ Misses 3333 3200 -133
- Partials 642 702 +60
Flags with carried forward coverage won't be shown. Click here to find out more.
Continue to review full report at Codecov.
|
There was a problem hiding this comment.
Directly commented in the previous suggestion #2285 (comment)
|
@alyakimenko in the meanwhile you could consider rebasing the git history to simplify the next review. |
cmd/root.go
Outdated
| if c.fallbackLogger == nil { | ||
| return nil, fmt.Errorf("fallback logger is nil") | ||
| } | ||
|
|
There was a problem hiding this comment.
Was this added because in some test this was true?
I think this is currently not possible to happen in the real code, so I am against there being an error for it ;) (and if it can happen here it needs to be added to the loki case as well
There was a problem hiding this comment.
@mstoykov This was mostly suggested by me. It should make easier the detection of eventual nil logger in any possible future change. It would be difficult to detect an issue just by testing and/or running some examples because it would be used only in case of an error of the main writer. And in the case, the panic would happen we are losing the main error generated by the writer. That is my thought about why I requested to have it. WDYT?
log/file.go
Outdated
| hook := &fileHook{ | ||
| fallbackLogger: fallbackLogger, | ||
| ch: make(chan []byte), | ||
| path: defaultLogfilePath, |
There was a problem hiding this comment.
I don't think this needs a defaultLogFilePath especially as it will just log somewhere on hte system. Additionally the current one is Posix specific and likely will have problems on windows.
I do propose that for a first release we :
- don't have a default one
- if we decide to have one, it to actually be in the current directory, but I think this needs to be discussed more so let's open an issue instead ?
There was a problem hiding this comment.
I agree with your proposal
There was a problem hiding this comment.
I got rid of the default log file path
log/file.go
Outdated
| if fallbackLogger != nil { | ||
| hook.fallbackLogger = fallbackLogger | ||
| } | ||
|
|
There was a problem hiding this comment.
again afaik there is no case (outside of some tests I guess) where fallbackLogger will be nil so if it's nil it's a much bigger issue and IMO worthy of a panic.
log/file.go
Outdated
| if err := os.MkdirAll(dir, os.ModePerm); err != nil { | ||
| return fmt.Errorf("failed to create dir for logfile %s: %w", h.path, err) | ||
| } |
There was a problem hiding this comment.
I kind of feel like we shouldn't just be creating directories for users if they don't exist, I am much more for erroring out and letting the user create the directory with the permissions they want.
There was a problem hiding this comment.
I replaced the mkdir logic with a check for the existence of a directory.
log/file.go
Outdated
| ) (logrus.Hook, error) { | ||
| hook := &fileHook{ | ||
| fallbackLogger: fallbackLogger, | ||
| ch: make(chan []byte), |
There was a problem hiding this comment.
Maybe this should be buffered. As it stands we won't block the first Log that gets fired but the one after that will block on the channel(given that it happens fast enough). IMO we either drop the channel or we have some buffering so at least for some burst it won't block at all. I don't have a particular value, but likely something like 100 will be enough, adding it as a configuration option might be a good idea but can also be left for a following PR and just have it as a constant for now.
WDYT.
There was a problem hiding this comment.
I made it buffered and defined fileHookDataChDefaultSize constant with a value of 100.
| return fmt.Errorf("failed to open logfile %s: %w", h.path, err) | ||
| } | ||
|
|
||
| h.w = file |
There was a problem hiding this comment.
Maybe we should have this buffered? I remember that there were some benchmarks showing considerable speedup
There was a problem hiding this comment.
I made it buffered. But I kept the underlying io.WriteCloser in order to have the ability to close a file on exit.
@codebien I also returned the loggerStopped channel to properly flush when work is done.
log/file.go
Outdated
| ) | ||
|
|
||
| // defaultLogfilePath is a default logfile path. | ||
| const defaultLogfilePath = "/tmp/k6run.log" |
There was a problem hiding this comment.
I wouldn't expect this to work on anything else than a Linux system. I would recommend to use something along the lines of: const defaultLogFilePath = filepath.Join(os.TempDir(), "k6run.log") instead 😸
Also, in order to be good citizens on our users OS', I would recommend to write the log files in a k6 subfolder too. To do so, I would tend to split things a bit for clarity of intent; something along those lines would do:
const defaultLogFolder = filepath.Join(os.TempDir(), "k6")
const defaultLogFilePath = filepath.Join(defaultLogFolder, "k6run.log")There was a problem hiding this comment.
#2285 (comment) I'm for the plan suggested there but this can be a valid alternative to discuss in the issue
There was a problem hiding this comment.
I'll leave it up to you @alyakimenko and @mstoykov to figure out what makes most sense 😸
log/file.go
Outdated
|
|
||
| // createOpenFile opens logfile by provided path, | ||
| // it will create a file if it doesn't exist. | ||
| func (h *fileHook) createOpenFile() error { |
There was a problem hiding this comment.
I find the name of this function quite unconventional, as it groups two operations that are exclusive: creating and opening a file. I would recommend to modify the signature to openFile(create bool) instead. Then the body could produce the proper opening flags by doing something along the lines of:
flags := os.O_WRONLY | os.O_APPEND
if create {
flags = flags | os.O_CREATE
}There was a problem hiding this comment.
I find the name of this function quite unconventional
IMHO, it would make sense in the case it would be an exported method so a public API for this struct. But it's something internal for wrapping the OR logic. If we delegate the input again then better to have directly the entire logic in the caller, otherwise we have just one more layer of logic where we could generate a failure.
Maybe we can improve the name? Just a suggestion, I don't have one better at the moment.
| func (h *fileHook) createOpenFile() error { | |
| func (h *fileHook) openOrCreateFile() error { |
There was a problem hiding this comment.
I've given this a bit more thought and, given the choice, I do think I'd prefer to get rid of this helper function all in all.
If we were to keep the function, I find that the naming is not the issue. Whether you open, or create the file ends up in the same underlying standard library call, and system call. It's always technically opening a file, with, in one scenario the instruction to not fail if it doesn't exist, but have the OS create it instead. But I'm really, REALLY, nitpicking on this, and I really don't want it to be a blocker! (from my point of view, it's not)
| return fmt.Errorf("failed to open logfile %s: %w", h.path, err) | ||
| } | ||
|
|
||
| h.w = file |
There was a problem hiding this comment.
I'm in line with Mihail on this and would recommend using bufio.NewWriter(f) here instead.
log/file_test.go
Outdated
| logger.Info("example log line") | ||
|
|
||
| cancel() | ||
| <-hook.dataCh | ||
|
|
||
| assert.Contains(t, buffer.String(), "example log line") |
There was a problem hiding this comment.
This test now fails. This (IMO) is because we now have a buffered channel between logger.Info -> ... -> fileHook.Fire and the actual place it's logged (the loop).
With a buffered channel (as long as there is space) the send (in Fire) can just put it in the channel and continue. With an unbuffered channel (as before) the send needs to wait for the actual receive on the channel to happen, before it can continue.
The latter will always manage to enter the select and write the message, the first won't. I don't think we care about losing the last few messages in some cases, as in the real case that should not be possible. But we still need this test to pass, so please add a small sleep and do -race -count 10 a few times locally to be sure it's enough. I would wager anything above 1-10ms should be sufficient
There was a problem hiding this comment.
With the timeout, it works as expected. Thanks!
There are a few complaints from linter:
log/file.go:21:1 stylecheck ST1000: at least one file in a package should have a package comment
log/levels.go:21:1 stylecheck ST1000: at least one file in a package should have a package comment
Should I worry about them?
There was a problem hiding this comment.
@alyakimenko Yes, please. The linter must be fixed for getting the PR merged.
There was a problem hiding this comment.
@codebien
Package log implements various logrus hooks.
Do you find the description suitable for the package?
There was a problem hiding this comment.
@alyakimenko it's what it does so it's fine for me, but other reviewers could have different opinions
There was a problem hiding this comment.
Hi @alyakimenko, thanks for the improvements. I spot few suggestions, also the linter should be fixed 🙏
log/file_test.go
Outdated
| time.Sleep(10 * time.Millisecond) | ||
|
|
||
| cancel() | ||
| <-hook.loggerStoppedCh |
There was a problem hiding this comment.
| time.Sleep(10 * time.Millisecond) | |
| cancel() | |
| <-hook.loggerStoppedCh | |
| cancel() | |
| <-nc.closed |
I would prefer to remove the time for asserting concurrency, I think we can benefit from the Close method of the WriteCloser in this case.
type nopCloser struct {
io.Writer
closed chan struct{}
}
func (nc *nopCloser) Close() error {
nc.closed <- struct{}{}
return nil
}
There was a problem hiding this comment.
This is a good suggestion. I applied it :)
There was a problem hiding this comment.
Looks like, It didn't help :(
There was a problem hiding this comment.
How would you like it if I brought the timeout back?
There was a problem hiding this comment.
Yep, I'm sorry this was my fault, the problem is with the Write sync order. You should restore the timeout. 😔
There was a problem hiding this comment.
I restored the timeout.
There was a problem hiding this comment.
Hi @alyakimenko, due to some refactorings you now will need to rebase this PR on master, sorry for the inconvience :(
|
@mstoykov Hello! I've finished rebasing |
|
@alyakimenko I think you didn't pull the upstream changes before rebasing :( |
|
@mstoykov Sorry, it's my bad. I fixed it. |
log/file.go
Outdated
| loglines := make(chan []byte, fileHookBufferSize) | ||
|
|
||
| go func() { | ||
| defer close(loglines) |
There was a problem hiding this comment.
Closing this can get us into panic as Fire is the one writing. There also isn't really any reason to do this - loop is the only place that reads from it, and it's exiting here so we won't stop anything closing it.
There was a problem hiding this comment.
Yeah, that makes sense. Thank you. I removed the defer.
Added file hook for logger.
Examples of usage:
With a defined log level:
Closes #2249