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

trace: nicer traces in tests, clean up trace configuration #766

Merged
merged 1 commit into from
Dec 10, 2020

Conversation

hawkw
Copy link
Contributor

@hawkw hawkw commented Dec 10, 2020

This branch improves how traces are displayed in tests. In particular,
I've made the following changes:

  • When running tests, use a "test writer" that participates in libtest's
    output capturing. Now, traces from tests will be displayed grouped
    together when the test fails, rather than printed to the console as
    soon as they occur. Logs can now be printed for successful tests using
    cargo test -- --show-output, and will still be grouped by test.
  • Because test traces are now captured, enable a more verbose default
    filter for tests. The logs will no longer be spammed to the console,
    so it's okay to have more verbose logging on by default when tests
    fail.
  • Disabled thread IDs in test mode. The tests run single-threaded
    proxies, and the new-style stack tests are completely single threaded.
    Some of the integration tests spawn test clients or servers in
    background threads, but those have their own spans which should make
    it much clearer to figure out where logs came from than just a numeric
    thread ID. Removing IDs makes the log lines a little shorter.

I considered also enabling thread names in the test logs (since the name
of a test thread is the name of the test it's running). I decided not
to, as they end up being quite long since the module path of the test
function is also incldued, and --show-output and panic output already
groups the logs by which test output them. However, we could turn thread
names on if we want to.

I also refactored the code for setting up tracing a bit. Hopefully it's
clearer now --- I was able to remove some complexity from how we pass
around the handle for reloading the trace level.

I also bumped some of the more verbose logs from the test support code
down to trace, since they get kinda annoying to have them on by
default (particularly the "new service" one).

This branch improves how traces are displayed in tests. In particular,
I've made the following changes:

* When running tests, use a "test writer" that participates in libtest's
  output capturing. Now, traces from tests will be displayed grouped
  together when the test fails, rather than printed to the console as
  soon as they occur. Logs can now be printed for successful tests using
  `cargo test -- --show-output`, and will still be grouped by test.
* Because test traces are now captured, enable a more verbose default
  filter for tests. The logs will no longer be spammed to the console,
  so it's okay to have more verbose logging on by default when tests
  fail.
* Disabled thread IDs in test mode. The tests run single-threaded
  proxies, and the new-style stack tests are completely single threaded.
  Some of the integration tests spawn test clients or servers in
  background threads, but those have their own spans which should make
  it much clearer to figure out where logs came from than just a numeric
  thread ID. Removing IDs makes the log lines a little shorter.

I considered also enabling thread names in the test logs (since the name
of a test thread is the name of the test it's running). I decided not
to, as they end up being quite long since the module path of the test
function is also incldued, and `--show-output` and panic output already
groups the logs by which test output them. However, we could turn thread
names on if we want to.

I also refactored the code for setting up tracing a bit. Hopefully it's
clearer now --- I was able to remove some complexity from how we pass
around the handle for reloading the trace level.

I also bumped some of the more verbose logs from the test support code
down to `trace`, since they get kinda annoying to have them on by
default (particularly the "new service" one).
@hawkw hawkw requested review from olix0r and a team December 10, 2020 20:11
Copy link
Member

@olix0r olix0r left a comment

Choose a reason for hiding this comment

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

lgtm

@hawkw hawkw merged commit 7f6159d into main Dec 10, 2020
@hawkw hawkw deleted the eliza/even-nicer-test-traces branch December 10, 2020 20:28
hawkw added a commit that referenced this pull request Dec 14, 2020
PR #766 changed the proxy tests to set a much more verbose default log
filter, relying on libtest's output capturing to prevent the tests from
spamming stdout when they don't fail. However, the integration tests run
the proxy in a separate thread, and libtest can't currently capture
output from spawned threads. This results in a bunch of unnecessary
noise when running the integration tests.

This branch changes the integration tests so that the spawned proxy
thread uses the old filter settings instead. We still get more detailed
output from stack tests, and from the main test threads in the
integration tests. I removed some code that would set the value of the
log level env vars, since that made this impossible — I'm not really
sure why that code was ever necessary in the first place.

Also, I fixed a compiler error in `linkerd2-app-test` due to a missing
Cargo feature.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
olix0r pushed a commit that referenced this pull request Dec 15, 2020
PR #766 changed the proxy tests to set a much more verbose default log
filter, relying on libtest's output capturing to prevent the tests from
spamming stdout when they don't fail. However, the integration tests run
the proxy in a separate thread, and libtest can't currently capture
output from spawned threads. This results in a bunch of unnecessary
noise when running the integration tests.

This branch changes the integration tests so that the spawned proxy
thread uses the old filter settings instead. We still get more detailed
output from stack tests, and from the main test threads in the
integration tests. I removed some code that would set the value of the
log level env vars, since that made this impossible — I'm not really
sure why that code was ever necessary in the first place.

Also, I fixed a compiler error in `linkerd2-app-test` due to a missing
Cargo feature.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
olix0r added a commit to linkerd/linkerd2 that referenced this pull request Dec 15, 2020
This release features a change to the proxy's cache eviction strategy to
ensure that clients (and their load balancers) are reused by new
outbound connections. This can dramatically reduce memory consumption,
especially for busy HTTP/1.1 clients.

Also, the proxy's HTTP detection scheme has been made more robust.
Previously, the proxy would perform a only single read to determine
whether a TCP stream was HTTP, which could lead to false positives. Now,
the proxy reads until at least the first newline, which is what the HTTP
parser actually needs to make a proper determination. With this, the
default dispatch timeouts have been increased to 5s to accomodate
connection pools that may not issue an immediate request.

Furthermore, this release includes an upgrade to Tokio v0.3 and its
associated ecosystem.

---

* update buffers to use Tokio 0.3 MPSC channels (linkerd/linkerd2-proxy#759)
* Update the proxy to use Tokio 0.3  (linkerd/linkerd2-proxy#732)
* Rename DetectHttp to NewServeHttp (linkerd/linkerd2-proxy#760)
* http: more consistent names for body types (linkerd/linkerd2-proxy#761)
* io: simplify the `Io` trait (linkerd/linkerd2-proxy#762)
* trace: nicer traces in tests, clean up trace configuration (linkerd/linkerd2-proxy#766)
* Ensure that services are held as long they are being used (linkerd/linkerd2-proxy#767)
* outbound: add stack tests for http (linkerd/linkerd2-proxy#765)
* cache: Ensure that actively held services are not evicted (linkerd/linkerd2-proxy#768)
* cache: Only spawn a single task per cache entry (linkerd/linkerd2-proxy#770)
* test: make integration tests shut up (linkerd/linkerd2-proxy#771)
* metrics: Add support for microsecond counters (linkerd/linkerd2-proxy#772)
* Add a protocol label to stack metrics (linkerd/linkerd2-proxy#773)
* detect: Make protocol detection more robust (linkerd/linkerd2-proxy#744)
olix0r added a commit to linkerd/linkerd2 that referenced this pull request Dec 15, 2020
This release features a change to the proxy's cache eviction strategy to
ensure that clients (and their load balancers) are reused by new
outbound connections. This can dramatically reduce memory consumption,
especially for busy HTTP/1.1 clients.

Also, the proxy's HTTP detection scheme has been made more robust.
Previously, the proxy would perform a only single read to determine
whether a TCP stream was HTTP, which could lead to false positives. Now,
the proxy reads until at least the first newline, which is what the HTTP
parser actually needs to make a proper determination. With this, the
default dispatch timeouts have been increased to 5s to accomodate
connection pools that may not issue an immediate request.

Furthermore, this release includes an upgrade to Tokio v0.3 and its
associated ecosystem.

---

* update buffers to use Tokio 0.3 MPSC channels (linkerd/linkerd2-proxy#759)
* Update the proxy to use Tokio 0.3  (linkerd/linkerd2-proxy#732)
* Rename DetectHttp to NewServeHttp (linkerd/linkerd2-proxy#760)
* http: more consistent names for body types (linkerd/linkerd2-proxy#761)
* io: simplify the `Io` trait (linkerd/linkerd2-proxy#762)
* trace: nicer traces in tests, clean up trace configuration (linkerd/linkerd2-proxy#766)
* Ensure that services are held as long they are being used (linkerd/linkerd2-proxy#767)
* outbound: add stack tests for http (linkerd/linkerd2-proxy#765)
* cache: Ensure that actively held services are not evicted (linkerd/linkerd2-proxy#768)
* cache: Only spawn a single task per cache entry (linkerd/linkerd2-proxy#770)
* test: make integration tests shut up (linkerd/linkerd2-proxy#771)
* metrics: Add support for microsecond counters (linkerd/linkerd2-proxy#772)
* Add a protocol label to stack metrics (linkerd/linkerd2-proxy#773)
* detect: Make protocol detection more robust (linkerd/linkerd2-proxy#744)
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.

2 participants