refactor: Add safety to the tests, add ability to catch stderr logs and add output path validation #552

fredcarle · 2022-06-22T16:50:05Z

Relevant issue(s)

Resolves #551
Resolves #550
Resolves #556

Description

This PR helps to solve the issue of too many open files on some systems due to loggers being added (without clearing the old ones) with every call to getLogger. We change the registry type from map[string][]Logger to map[string]Logger and make the corresponding adjustment for the registry functions to work without a slice.

Changes were applied to the test functions to limit panics when something goes wrong.

Added an explicit setConfig before the test case loop on TestLogDoesntWriteMessagesToLogGivenNoLogPath to make it clear when using go test ./logging -v that the logged errors are do to a filepath error in this test.

Tasks

I made sure the code is well commented, particularly hard-to-understand areas.
I made sure the repository-held documentation is changed accordingly.
I made sure the pull request title adheres to the conventional commit style (the subset used in the project can be found in tools/configs/chglog/config.yml).
I made sure to discuss its limitations such as threats to validity, vulnerability to mistake and misuse, robustness to invalidation of assumptions, resource requirements, ...

How has this been tested?

go test ./logging -v

Specify the platform(s) on which this was tested:

MacOS

codecov · 2022-06-22T16:54:47Z

Codecov Report

Merging #552 (52f9993) into develop (5312801) will decrease coverage by 0.03%.
The diff coverage is 79.16%.

❗ Current head 52f9993 differs from pull request most recent head 3cb181e. Consider uploading reports for the commit 3cb181e to get more accurate results

@@             Coverage Diff             @@
##           develop     #552      +/-   ##
===========================================
- Coverage    54.73%   54.70%   -0.04%     
===========================================
  Files           97       97              
  Lines        13149    13195      +46     
===========================================
+ Hits          7197     7218      +21     
- Misses        5287     5306      +19     
- Partials       665      671       +6

Impacted Files	Coverage Δ
logging/logging.go	`100.00% <ø> (ø)`
logging/registry.go	`100.00% <ø> (ø)`
logging/config.go	`76.56% <72.22%> (-10.68%)`	⬇️
logging/logger.go	`78.81% <100.00%> (-4.21%)`	⬇️

AndrewSisley

question: How does this sove the 'file not found' errors that we saw in the logs? (I assume it does, I just cant tell how - best guess is that you are 'losing' existing entries in the register and the errors came from previously registered loggers)

logging/registry.go

logging/logging_test.go

fredcarle · 2022-06-22T18:58:21Z

question: How does this sove the 'file not found' errors that we saw in the logs? (I assume it does, I just cant tell how - best guess is that you are 'losing' existing entries in the register and the errors came from previously registered loggers)

It doesn't. It just makes it explicit where the file not found is from. I thought this was what you were trying to achieve with the TestLogDoesntWriteMessagesToLogGivenNoLogPath test. In the full test suite, There will never be no log path for this test unless we nuke the cached config prior to running the test. In the test you asserted a path error so that's what you wanted as the outcome.

AndrewSisley · 2022-06-22T19:08:28Z

In the full test suite, There will never be no log path for this test unless we nuke the cached config prior to running the test. In the test you asserted a path error so that's what you wanted as the outcome.

That sounds very much like a bug in the test suite (these tests should never be dependent on each other). If the assertion of the TestLogDoesntWriteMessagesToLogGivenNoLogPath test is based on a false assuption, then the assert of that test should change, not the setup for it (once the test suite dependency bug is fixed).

logging/registry.go

orpheuslummis · 2022-06-23T16:56:11Z

I wonder if this PR could additionally fix #556 or if that's too "distant" for it.

fredcarle · 2022-06-23T16:59:12Z

I wonder if this PR could additionally fix #556 or if that's too "distant" for it.

It does fix it 🙂

logging/logger.go

logging/logging_test.go

orpheuslummis · 2022-06-24T00:33:18Z

Just reporting that this PR at this point, empirically, does indeed solve #556 and gives the following test times:

linux: ok github.com/sourcenetwork/defradb/logging 0.248s ~12x faster than develop (at 3s)
macos: ok github.com/sourcenetwork/defradb/logging 7.790s ~4-5x faster than develop (36s)

logging/logging_test.go

AndrewSisley · 2022-06-24T18:44:31Z

logging/config.go

+			validatedPaths[i] = validatedPaths[len(validatedPaths)-1]
+			validatedPaths = validatedPaths[:len(validatedPaths)-1]
+		} else {
+			err := f.Close()


suggestion: If the paths are invalid and the file closes (that felt really odd to write - is this Close needed?), then no errors will be reported and stuff will continue as if nothing is wrong, logging only to console no? Would suggest panicing instead, or at the very least logging an error (kind of feels far more severe than an error, but fatal feels abusive) before trying to close the file.

If the paths are invalid and the file closes

How will this happen?

is this Close needed

If you open a file you should close it too.

How will this happen?

If the err on line 222 is nil

you don't reach line 222 if the path is invalid.

Ah I'm reading it backwards. The problem exists though - if you give it invalid paths then an empty collection will be returned and no errors logged - the logger will then only log to console, without any notification to anyone/thing that might be watching

(3) 👍
(6) I would imagine that the code would be easier to read if validatedPaths started off empty, and had validated values added to it, instead of initializing it with everything in it and then removing invalid items.
(7) We do not own the underlying file system, it is very possible for stuff to remove any files/paths created or validated here after this function has run.

Also, how do you think this applies here and not when someone updates the config file with a new output path?

I never suggested that it wouldn't be applicable on update. Of course it would.

I'll revisit with your suggestion.

I think this is out of scope of this PR. If you think it's worth spending time on, do you mind opening an issue for it?

I think this is out of scope of this PR. If you think it's worth spending time on, do you mind opening an issue for it?

Happy with that - the code is an improvement, and we can look at making it even better later. Will create ticket which can then be prioritized/dropped later.

orpheuslummis · 2022-06-25T17:05:38Z

Profiling the package with make clean:test && go test ./logging/ -count=100 -shuffle=on -cpuprofile cpu.prof && go tool pprof -http=localhost:8080 cpu.prof

Shows pprof's web UI which allows us to visualize the profiling data (here we chose CPU), like: (run the command yourself to have interactive view)

I note:

I find the flamegraph view to be the most intuitive
Only 53% of the time is "running the tests, rest is runtime
Within the tests, the majority of time spent is within zap

AndrewSisley

Nice! Thanks Fred for putting up with my comments here. Code looks good, and is a really nice speed boost/fix for the tests.

automatically done with `go mod tidy`

…nd add output path validation (sourcenetwork#552) Relevant issue(s) Resolves sourcenetwork#551 Resolves sourcenetwork#550 Resolves sourcenetwork#556 Description - This PR helps to solve the issue of too many open files on some systems due to loggers being added (without clearing the old ones) with every call to getLogger. - Changes were applied to the test functions to limit panics when something goes wrong. - Added validation of log paths. - Added log pipe for test that sent logs to stderr.

fredcarle added this to the DefraDB v0.3 milestone Jun 22, 2022

fredcarle requested a review from a team June 22, 2022 16:50

fredcarle self-assigned this Jun 22, 2022

AndrewSisley requested changes Jun 22, 2022

View reviewed changes

logging/registry.go Outdated Show resolved Hide resolved

logging/logging_test.go Outdated Show resolved Hide resolved

shahzadlone reviewed Jun 23, 2022

View reviewed changes

logging/registry.go Outdated Show resolved Hide resolved

AndrewSisley reviewed Jun 23, 2022

View reviewed changes

logging/logger.go Outdated Show resolved Hide resolved

AndrewSisley reviewed Jun 23, 2022

View reviewed changes

logging/logging_test.go Outdated Show resolved Hide resolved

AndrewSisley reviewed Jun 23, 2022

View reviewed changes

logging/logging_test.go Outdated Show resolved Hide resolved

fredcarle changed the title ~~refactor: Change the logging registry and add safety to the tests~~ refactor: Add safety to the tests, add ability to catch stderr logs and add output path validation Jun 24, 2022

shahzadlone reviewed Jun 24, 2022

View reviewed changes

logging/logging_test.go Show resolved Hide resolved

AndrewSisley reviewed Jun 24, 2022

View reviewed changes

logging/logging_test.go Show resolved Hide resolved

AndrewSisley reviewed Jun 24, 2022

View reviewed changes

fredcarle force-pushed the fredcarle/refactor/logging branch 2 times, most recently from 43a6fca to 2bce7f2 Compare June 24, 2022 19:20

orpheuslummis mentioned this pull request Jun 27, 2022

chore: Enable random execution order of tests #554

Merged

4 tasks

AndrewSisley approved these changes Jun 27, 2022

View reviewed changes

AndrewSisley mentioned this pull request Jun 27, 2022

Zapper errors can leak out to the user #565

Closed

change the registry to single logger per name

5e25240

fredcarle added 25 commits June 27, 2022 15:07

change pre test case config to be explicit

89687e8

fix getLines to close open file after access

d0333dc

change error handling to prevent test from panicing

51ca8cc

change require order to be alphabetical

a0db87c

automatically done with `go mod tidy`

change to more descriptive path string

d1ae4f5

change the registry back to it’s original version

c2f7341

add path validation

45d4cf9

add registry clearing and zap stdout catch

927aa99

remove type from registry definition

592f0bc

add error check for file.Close

deeef97

add log to the logging package

947340c

move clearing to start of tests with defer

8e0b841

change observer for a pipe

a5350b0

remove stderr when piping

df3d637

remove withOption

1502444

add test specifying stderr output

9df8e3c

change sending to pipe only when specifically sending to stderr

cd7f361

add stderr constant

df1cf5e

add test of logger with pipe but valid path

0de6392

update os.IsNotExist to new idiomatic format

b6357cb

add copy of paths

beeaea1

change from Create to OpenFile

2b4c833

add log when file path is not valid

512a8ec

change validation to append only

47b9498

fix unnecessary white space

3cb181e

fredcarle force-pushed the fredcarle/refactor/logging branch from 52f9993 to 3cb181e Compare June 27, 2022 19:07

fredcarle merged commit a3e8279 into develop Jun 27, 2022

fredcarle deleted the fredcarle/refactor/logging branch June 27, 2022 19:11

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

refactor: Add safety to the tests, add ability to catch stderr logs and add output path validation #552

refactor: Add safety to the tests, add ability to catch stderr logs and add output path validation #552

fredcarle commented Jun 22, 2022 •

edited

Loading

codecov bot commented Jun 22, 2022 •

edited

Loading

AndrewSisley left a comment

fredcarle commented Jun 22, 2022

AndrewSisley commented Jun 22, 2022

orpheuslummis commented Jun 23, 2022

fredcarle commented Jun 23, 2022

orpheuslummis commented Jun 24, 2022

AndrewSisley Jun 24, 2022

fredcarle Jun 24, 2022

AndrewSisley Jun 24, 2022

fredcarle Jun 24, 2022

AndrewSisley Jun 24, 2022

AndrewSisley Jun 27, 2022 •

edited

Loading

fredcarle Jun 27, 2022

fredcarle Jun 27, 2022

AndrewSisley Jun 27, 2022

AndrewSisley Jun 27, 2022

orpheuslummis commented Jun 25, 2022

AndrewSisley left a comment

refactor: Add safety to the tests, add ability to catch stderr logs and add output path validation #552

refactor: Add safety to the tests, add ability to catch stderr logs and add output path validation #552

Conversation

fredcarle commented Jun 22, 2022 • edited Loading

Relevant issue(s)

Description

Tasks

How has this been tested?

codecov bot commented Jun 22, 2022 • edited Loading

Codecov Report

AndrewSisley left a comment

Choose a reason for hiding this comment

fredcarle commented Jun 22, 2022

AndrewSisley commented Jun 22, 2022

orpheuslummis commented Jun 23, 2022

fredcarle commented Jun 23, 2022

orpheuslummis commented Jun 24, 2022

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

AndrewSisley Jun 27, 2022 • edited Loading

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

orpheuslummis commented Jun 25, 2022

AndrewSisley left a comment

Choose a reason for hiding this comment

fredcarle commented Jun 22, 2022 •

edited

Loading

codecov bot commented Jun 22, 2022 •

edited

Loading

AndrewSisley Jun 27, 2022 •

edited

Loading