[Merged by Bors] - fix flaky test: TestSpacemeshApp_NodeService #4728

fasmat · 2023-07-19T12:38:54Z

Motivation

Closes: #4729

Changes

The app during initialization for set the logging level to zapcore.InfoLevel which overwrites what ever logging configuration is passed in via WithLog. This was fixed, the app still starts up with zapcore.InfoLevel by default.
There has been an issue with logging in tests because the logging middleware for GRPC wasn't unset when the test ended which could result in components logging after the test ended and thereby failing a test. This is now done in app.stopServices (since it is set up in app.startServices)
After making logs visible the issue was identified: the node is shut down while it verifies its own post proof. This only happens on the macos-latest runner because other runners might not have completed their initial post proof yet or are already done verifying it by that time.
- Changed verifying to only emit and log errors when an error other than context.Cancelled is returned.
These changes allowed me to run the test 100 times in a row without it failing a single time:

go test -v -timeout 150s -run ^TestSpacemeshApp_NodeService$ github.com/spacemeshos/go-spacemesh/node -count 100

passes without a single iteration of the test failing.

Test Plan

n/a

TODO

Explain motivation or link existing issue(s)
Test changes and document test plan
Update documentation as needed

DevOps Notes

This PR does not require configuration changes (e.g., environment variables, GitHub secrets, VM resources)
This PR does not affect public APIs
This PR does not rely on a new version of external services (PoET, elasticsearch, etc.)
This PR does not make changes to log messages (which monitoring infrastructure may rely on)

codecov · 2023-07-19T12:54:08Z

Codecov Report

Merging #4728 (3cefb86) into develop (68d196b) will increase coverage by 0.2%.
The diff coverage is 58.8%.

@@            Coverage Diff            @@
##           develop   #4728     +/-   ##
=========================================
+ Coverage     77.0%   77.2%   +0.2%     
=========================================
  Files          255     255             
  Lines        28846   28855      +9     
=========================================
+ Hits         22213   22286     +73     
+ Misses        5250    5184     -66     
- Partials      1383    1385      +2

Impacted Files	Coverage Δ
activation/activation.go	`77.8% <55.5%> (-0.2%)`	⬇️
node/node.go	`65.5% <62.5%> (+0.2%)`	⬆️

... and 6 files with indirect coverage changes

fasmat · 2023-07-19T14:17:47Z

bors try

node/bad_peer_test.go

bors · 2023-07-19T15:10:56Z

try

Build failed:

ci-status

fasmat · 2023-07-19T15:41:51Z

bors merge

## Motivation Closes: #4729 ## Changes - The app during initialization for set the logging level to `zapcore.InfoLevel` which overwrites what ever logging configuration is passed in via `WithLog`. This was fixed, the app still starts up with `zapcore.InfoLevel` by default. - There has been an issue with logging in tests because the logging middleware for GRPC wasn't unset when the test ended which could result in components logging after the test ended and thereby failing a test. This is now done in `app.stopServices` (since it is set up in `app.startServices`) - After making logs visible the issue was identified: the node is shut down while it verifies its own post proof. This only happens on the `macos-latest` runner because other runners might not have completed their initial post proof yet or are already done verifying it by that time. - Changed verifying to only emit and log errors when an error other than `context.Cancelled` is returned. - These changes allowed me to run the test 100 times in a row without it failing a single time: ``` go test -v -timeout 150s -run ^TestSpacemeshApp_NodeService$ github.com/spacemeshos/go-spacemesh/node -count 100 ``` passes without a single iteration of the test failing. ## Test Plan n/a ## TODO  - [x] Explain motivation or link existing issue(s) - [x] Test changes and document test plan - [x] Update documentation as needed ## DevOps Notes  - [x] This PR does not require configuration changes (e.g., environment variables, GitHub secrets, VM resources) - [x] This PR does not affect public APIs - [x] This PR does not rely on a new version of external services (PoET, elasticsearch, etc.) - [x] This PR does not make changes to log messages (which monitoring infrastructure may rely on)

bors · 2023-07-19T16:02:53Z

Build failed:

systest-status

fasmat · 2023-07-19T16:11:28Z

bors merge

## Motivation Closes: #4729 ## Changes - The app during initialization for set the logging level to `zapcore.InfoLevel` which overwrites what ever logging configuration is passed in via `WithLog`. This was fixed, the app still starts up with `zapcore.InfoLevel` by default. - There has been an issue with logging in tests because the logging middleware for GRPC wasn't unset when the test ended which could result in components logging after the test ended and thereby failing a test. This is now done in `app.stopServices` (since it is set up in `app.startServices`) - After making logs visible the issue was identified: the node is shut down while it verifies its own post proof. This only happens on the `macos-latest` runner because other runners might not have completed their initial post proof yet or are already done verifying it by that time. - Changed verifying to only emit and log errors when an error other than `context.Cancelled` is returned. - These changes allowed me to run the test 100 times in a row without it failing a single time: ``` go test -v -timeout 150s -run ^TestSpacemeshApp_NodeService$ github.com/spacemeshos/go-spacemesh/node -count 100 ``` passes without a single iteration of the test failing. ## Test Plan n/a ## TODO  - [x] Explain motivation or link existing issue(s) - [x] Test changes and document test plan - [x] Update documentation as needed ## DevOps Notes  - [x] This PR does not require configuration changes (e.g., environment variables, GitHub secrets, VM resources) - [x] This PR does not affect public APIs - [x] This PR does not rely on a new version of external services (PoET, elasticsearch, etc.) - [x] This PR does not make changes to log messages (which monitoring infrastructure may rely on)

bors · 2023-07-19T16:42:25Z

Build failed:

ci-status

node/node_test.go

fasmat · 2023-07-20T07:58:29Z

bors merge

## Motivation Closes: #4729 ## Changes - The app during initialization for set the logging level to `zapcore.InfoLevel` which overwrites what ever logging configuration is passed in via `WithLog`. This was fixed, the app still starts up with `zapcore.InfoLevel` by default. - There has been an issue with logging in tests because the logging middleware for GRPC wasn't unset when the test ended which could result in components logging after the test ended and thereby failing a test. This is now done in `app.stopServices` (since it is set up in `app.startServices`) - After making logs visible the issue was identified: the node is shut down while it verifies its own post proof. This only happens on the `macos-latest` runner because other runners might not have completed their initial post proof yet or are already done verifying it by that time. - Changed verifying to only emit and log errors when an error other than `context.Cancelled` is returned. - These changes allowed me to run the test 100 times in a row without it failing a single time: ``` go test -v -timeout 150s -run ^TestSpacemeshApp_NodeService$ github.com/spacemeshos/go-spacemesh/node -count 100 ``` passes without a single iteration of the test failing. ## Test Plan n/a ## TODO  - [x] Explain motivation or link existing issue(s) - [x] Test changes and document test plan - [x] Update documentation as needed ## DevOps Notes  - [x] This PR does not require configuration changes (e.g., environment variables, GitHub secrets, VM resources) - [x] This PR does not affect public APIs - [x] This PR does not rely on a new version of external services (PoET, elasticsearch, etc.) - [x] This PR does not make changes to log messages (which monitoring infrastructure may rely on)

bors · 2023-07-20T08:47:41Z

Pull request successfully merged into develop.

Build succeeded!

The publicly hosted instance of bors-ng is deprecated and will go away soon.

If you want to self-host your own instance, instructions are here.
For more help, visit the forum.

If you want to switch to GitHub's built-in merge queue, visit their help page.

This reverts commit e91d735.

## Motivation #4728 broke debug logging, this reverts part of the PR to make it possible to log debug messages again when enabled via config. ## Changes Revert some changes from #4728 ## Test Plan n/a ## TODO  - [x] Explain motivation or link existing issue(s) - [x] Test changes and document test plan - [x] Update documentation as needed ## DevOps Notes  - [x] This PR does not require configuration changes (e.g., environment variables, GitHub secrets, VM resources) - [x] This PR does not affect public APIs - [x] This PR does not rely on a new version of external services (PoET, elasticsearch, etc.) - [x] This PR does not make changes to log messages (which monitoring infrastructure may rely on)

This reverts commit e91d735.

…shos#4728)"" This reverts commit f87546d.

fasmat self-assigned this Jul 19, 2023

fasmat force-pushed the investigate-failing-test branch from 03a28ef to f4ef0fb Compare July 19, 2023 14:17

fasmat marked this pull request as ready for review July 19, 2023 14:17

fasmat requested review from countvonzero, dshulyak and poszu as code owners July 19, 2023 14:17

bors bot added a commit that referenced this pull request Jul 19, 2023

Try #4728:

1f8b118

countvonzero approved these changes Jul 19, 2023

View reviewed changes

node/bad_peer_test.go Show resolved Hide resolved

fasmat changed the title ~~flaky test: ongoing investigation, do not merge~~ fix flaky test: TestSpacemeshApp_NodeService Jul 19, 2023

poszu reviewed Jul 20, 2023

View reviewed changes

node/node_test.go Outdated Show resolved Hide resolved

fasmat added 9 commits July 20, 2023 07:57

Fix logging setup for App

6bc7407

Temporary disable all os except macos-latest

3be5f20

Proper cleanup on test shutdown

5efbeec

Move reset of grpc logging middleware to app shutdown

20990b0

Increase logging level back to error

8ae0f07

Cleanup

24c9db8

Revert disabling runners

1eb2ea3

Possible fix for failing test

0aca056

Use t.TempDir()

3cefb86

fasmat force-pushed the investigate-failing-test branch from c58c25c to 3cefb86 Compare July 20, 2023 07:58

bors bot changed the title ~~fix flaky test: TestSpacemeshApp_NodeService~~ [Merged by Bors] - fix flaky test: TestSpacemeshApp_NodeService Jul 20, 2023

bors bot closed this Jul 20, 2023

bors bot deleted the investigate-failing-test branch July 20, 2023 08:47

dshulyak added a commit to dshulyak/go-spacemesh that referenced this pull request Jul 21, 2023

Revert "fix flaky test: TestSpacemeshApp_NodeService (spacemeshos#4728)"

20a69b2

This reverts commit e91d735.

fasmat mentioned this pull request Jul 21, 2023

[Merged by Bors] - Fix debug logging #4739

Closed

7 tasks

dshulyak added a commit to dshulyak/go-spacemesh that referenced this pull request Jul 21, 2023

Revert "fix flaky test: TestSpacemeshApp_NodeService (spacemeshos#4728)"

f87546d

This reverts commit e91d735.

dshulyak added a commit to dshulyak/go-spacemesh that referenced this pull request Jul 22, 2023

Revert "Revert "fix flaky test: TestSpacemeshApp_NodeService (spaceme…

acc86f7

…shos#4728)"" This reverts commit f87546d.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Merged by Bors] - fix flaky test: TestSpacemeshApp_NodeService #4728

[Merged by Bors] - fix flaky test: TestSpacemeshApp_NodeService #4728

fasmat commented Jul 19, 2023 •

edited

codecov bot commented Jul 19, 2023 •

edited

fasmat commented Jul 19, 2023

bors bot commented Jul 19, 2023

fasmat commented Jul 19, 2023

bors bot commented Jul 19, 2023

fasmat commented Jul 19, 2023

bors bot commented Jul 19, 2023

fasmat commented Jul 20, 2023

bors bot commented Jul 20, 2023

[Merged by Bors] - fix flaky test: TestSpacemeshApp_NodeService #4728

[Merged by Bors] - fix flaky test: TestSpacemeshApp_NodeService #4728

Conversation

fasmat commented Jul 19, 2023 • edited

Motivation

Changes

Test Plan

TODO

DevOps Notes

codecov bot commented Jul 19, 2023 • edited

Codecov Report

fasmat commented Jul 19, 2023

bors bot commented Jul 19, 2023

try

fasmat commented Jul 19, 2023

bors bot commented Jul 19, 2023

fasmat commented Jul 19, 2023

bors bot commented Jul 19, 2023

fasmat commented Jul 20, 2023

bors bot commented Jul 20, 2023

fasmat commented Jul 19, 2023 •

edited

codecov bot commented Jul 19, 2023 •

edited