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

app: initialize tracing prior to parsing env vars #425

Merged
merged 1 commit into from
Feb 3, 2020

Conversation

hawkw
Copy link
Contributor

@hawkw hawkw commented Feb 3, 2020

Before migrating from env_logger to tracing, the proxy set up
logging before trying to read a configuration from the environment. This
meant that any errors that occurred while parsing env vars could be
logged at the error level and would be displayed to the user. Since we
log these errors when they occur, the formatted output from the error
types the parsing methods return is pretty minimal.

When we switched to tracing, we moved the tracing initialization so
that it occurs after parsing the config from the env. This means that
the event macros for config errors now occur when there is no tracing
subscriber to collect and format them. Currently, if an env var is
malformed, we see something like this:

$ LINKERD2_PROXY_DESTINATION_SVC_ADDR="bad" cargo run
    Finished dev [unoptimized] target(s) in 0.20s
     Running `target/debug/linkerd2-proxy`
Invalid configuration: invalid environment variable

This is not terribly helpful. More complex misconfigurations, like the
requirement that if LINKERD2_PROXY_IDENTITY_DISABLED is set,
LINEKRD2_PROXY_TAP_DISABLED must also be set, are very difficult to
diagnose: For example:

$ LINKERD2_PROXY_DESTINATION_SVC_ADDR=127.0.0.1:42069 \
  LINKERD2_PROXY_IDENTITY_DISABLED=yes \
  cargo run
    Finished dev [unoptimized] target(s) in 0.41s
     Running `target/debug/linkerd2-proxy`
Invalid configuration: invalid environment variable

This commit moves the tracing initialization to occur before parsing
the config. Now, any errors parsing the configuration from the
environment are once again logged, and all is right in the world:

$ LINKERD2_PROXY_DESTINATION_SVC_ADDR="bad" cargo run
    Finished dev [unoptimized] target(s) in 0.55s
     Running `target/debug/linkerd2-proxy`
ignoring ``: invalid filter directive
[     0.47490772s] ERROR linkerd2_app::env: LINKERD2_PROXY_IDENTITY_DISABLED must be set or identity configuration must be specified.
[     0.47704003s] ERROR linkerd2_app::env: Not a valid address: bad
[     0.47743234s] ERROR linkerd2_app::env: LINKERD2_PROXY_DESTINATION_SVC_ADDR="bad" is not valid: AddrError(MissingPort)
[     0.47803128s] ERROR linkerd2_app::env: LINKERD2_PROXY_TAP_SVC_NAME must be set or tap must be disabled
Invalid configuration: invalid environment variable
$ LINKERD2_PROXY_DESTINATION_SVC_ADDR=127.0.0.1:42069 \
  LINKERD2_PROXY_IDENTITY_DISABLED=yes \
  cargo run
    Finished dev [unoptimized] target(s) in 0.24s
     Running `target/debug/linkerd2-proxy`
ignoring ``: invalid filter directive
[     0.48071794s] ERROR linkerd2_app::env: LINKERD2_PROXY_TAP_DISABLED must be set if identity is disabled
Invalid configuration: invalid environment variable

Signed-off-by: Eliza Weisman [email protected]

Before migrating from `env_logger` to `tracing`, the proxy set up
logging before trying to read a configuration from the environment. This
meant that any errors that occurred while parsing env vars could be
logged at the error level and would be displayed to the user. Since we
log these errors when they occur, the formatted output from the error
types the parsing methods return is pretty minimal.

When we switched to `tracing`, we moved the tracing initialization so
that it occurs _after_ parsing the config from the env. This means that
the event macros for config errors now occur when there is no `tracing`
subscriber to collect and format them. Currently, if an env var is
malformed, we see something like this:

```console
:; LINKERD2_PROXY_DESTINATION_SVC_ADDR="bad" cargo run
    Finished dev [unoptimized] target(s) in 0.20s
     Running `target/debug/linkerd2-proxy`
Invalid configuration: invalid environment variable
```

This is not terribly helpful. More complex misconfigurations, like the
requirement that if `LINKERD2_PROXY_IDENTITY_DISABLED` is set,
`LINEKRD2_PROXY_TAP_DISABLED` must also be set, are very difficult to
diagnose: For example:

```console
:; LINKERD2_PROXY_DESTINATION_SVC_ADDR=127.0.0.1:42069 \
   LINKERD2_PROXY_IDENTITY_DISABLED=yes \
   cargo run
    Finished dev [unoptimized] target(s) in 0.41s
        Running `target/debug/linkerd2-proxy`
Invalid configuration: invalid environment variable
```

This commit moves the tracing initialization to occur *before* parsing
the config. Now, any errors parsing the configuration from the
environment are once again logged, and all is right in the world:

```console
:; LINKERD2_PROXY_DESTINATION_SVC_ADDR="bad" cargo run
    Finished dev [unoptimized] target(s) in 0.55s
     Running `target/debug/linkerd2-proxy`
ignoring ``: invalid filter directive
[     0.47490772s] ERROR linkerd2_app::env: LINKERD2_PROXY_IDENTITY_DISABLED must be set or identity configuration must be specified.
[     0.47704003s] ERROR linkerd2_app::env: Not a valid address: bad
[     0.47743234s] ERROR linkerd2_app::env: LINKERD2_PROXY_DESTINATION_SVC_ADDR="bad" is not valid: AddrError(MissingPort)
[     0.47803128s] ERROR linkerd2_app::env: LINKERD2_PROXY_TAP_SVC_NAME must be set or tap must be disabled
Invalid configuration: invalid environment variable
```

```console
:; LINKERD2_PROXY_DESTINATION_SVC_ADDR=127.0.0.1:42069 \
   LINKERD2_PROXY_IDENTITY_DISABLED=yes \
   cargo run
    Finished dev [unoptimized] target(s) in 0.24s
     Running `target/debug/linkerd2-proxy`
ignoring ``: invalid filter directive
[     0.48071794s] ERROR linkerd2_app::env: LINKERD2_PROXY_TAP_DISABLED must be set if identity is disabled
Invalid configuration: invalid environment variable
```

Signed-off-by: Eliza Weisman <[email protected]>
@hawkw hawkw requested a review from a team February 3, 2020 21:48
@hawkw hawkw merged commit 52cc869 into master Feb 3, 2020
@olix0r olix0r deleted the eliza/log-cfg-errors branch February 3, 2020 22:49
olix0r added a commit to linkerd/linkerd2 that referenced this pull request Feb 4, 2020
This release fixes a bug in the proxy's logging subsystem that could
cause the proxy to consume memory until the process is OOMKilled,
especially when the proxy was configured to log diagnostic information.

The proxy also now properly emits `grpc-status` headers when signaling
proxy errors to gRPC clients.

This release upgrades the proxy's Rust version, the `http` crate
dependency to address RUSTSEC-2019-0033 and RUSTSEC-2019-0034, and the
`prost` crate dependency has been patched to address RUSTSEC-2020-02.

---

* internal: Introduce a locking middleware (linkerd/linkerd2-proxy#408)
* Update to Rust 1.40 with new Cargo.lock format (linkerd/linkerd2-proxy#410)
* Update http to v0.1.21 (linkerd/linkerd2-proxy#412)
* internal: Split retry, http-classify, and http-metrics (linkerd/linkerd2-proxy#409)
* Actually update http to v0.1.21 (linkerd/linkerd2-proxy#413)
* patch `prost` 0.5 to pick up security fix (linkerd/linkerd2-proxy#414)
* metrics: Make Counter & Gauge atomic (linkerd/linkerd2-proxy#415)
* Set grpc-status headers on dispatch errors (linkerd/linkerd2-proxy#416)
* trace: update `tracing-subscriber` to 0.2.0-alpha.4 (linkerd/linkerd2-proxy#418)
* discover: Warn on discovery error (linkerd/linkerd2-proxy#422)
* router: Avoid large up-front allocations (linkerd/linkerd2-proxy#421)
* errors: Set correct HTTP version on responses (linkerd/linkerd2-proxy#424)
* app: initialize tracing prior to parsing env vars (linkerd/linkerd2-proxy#425)
* trace: update tracing-subscriber to 0.2.0-alpha.6 (linkerd/linkerd2-proxy#423)
adleong pushed a commit to linkerd/linkerd2 that referenced this pull request Feb 4, 2020
This release fixes a bug in the proxy's logging subsystem that could
cause the proxy to consume memory until the process is OOMKilled,
especially when the proxy was configured to log diagnostic information.

The proxy also now properly emits `grpc-status` headers when signaling
proxy errors to gRPC clients.

This release upgrades the proxy's Rust version, the `http` crate
dependency to address RUSTSEC-2019-0033 and RUSTSEC-2019-0034, and the
`prost` crate dependency has been patched to address RUSTSEC-2020-02.

---

* internal: Introduce a locking middleware (linkerd/linkerd2-proxy#408)
* Update to Rust 1.40 with new Cargo.lock format (linkerd/linkerd2-proxy#410)
* Update http to v0.1.21 (linkerd/linkerd2-proxy#412)
* internal: Split retry, http-classify, and http-metrics (linkerd/linkerd2-proxy#409)
* Actually update http to v0.1.21 (linkerd/linkerd2-proxy#413)
* patch `prost` 0.5 to pick up security fix (linkerd/linkerd2-proxy#414)
* metrics: Make Counter & Gauge atomic (linkerd/linkerd2-proxy#415)
* Set grpc-status headers on dispatch errors (linkerd/linkerd2-proxy#416)
* trace: update `tracing-subscriber` to 0.2.0-alpha.4 (linkerd/linkerd2-proxy#418)
* discover: Warn on discovery error (linkerd/linkerd2-proxy#422)
* router: Avoid large up-front allocations (linkerd/linkerd2-proxy#421)
* errors: Set correct HTTP version on responses (linkerd/linkerd2-proxy#424)
* app: initialize tracing prior to parsing env vars (linkerd/linkerd2-proxy#425)
* trace: update tracing-subscriber to 0.2.0-alpha.6 (linkerd/linkerd2-proxy#423)
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.

3 participants