Jaeger: Jaeger agent logs "0" whenever sampling strategies are requested

[agaudreault-jive]

Describe the bug
The jaeger agent is constantly logging 0 characters in the console whenever the /sampling endpoint is queried. This does not seem to be happening with the zap logger since the record is not formatted and changing the log level to error does not fix the behavior.

In production, most of our microservices refresh the remote sampling configuration every minutes causing pollution in the logs and in our Kibana as well since all the logstream is parsed.

2020/07/22 14:46:13 maxprocs: Updating GOMAXPROCS=1: using minimum allowed GOMAXPROCS
{"level":"info","ts":1595429173.690958,"caller":"flags/service.go:116","msg":"Mounting metrics handler on admin server","route":"/metrics"}
{"level":"info","ts":1595429173.6913276,"caller":"flags/admin.go:120","msg":"Mounting health check on admin server","route":"/"}
{"level":"info","ts":1595429173.691403,"caller":"flags/admin.go:126","msg":"Starting admin HTTP server","http-addr":":14271"}
{"level":"info","ts":1595429173.6914232,"caller":"flags/admin.go:112","msg":"Admin server started","http.host-port":"[::]:14271","health-status":"unavailable"}
{"level":"info","ts":1595429173.6923292,"caller":"grpc/builder.go:66","msg":"Agent requested insecure grpc connection to collector(s)"}
{"level":"info","ts":1595429173.6923819,"caller":"[email protected]/clientconn.go:106","msg":"parsed scheme: \"\"","system":"grpc","grpc_log":true}
{"level":"info","ts":1595429173.6924126,"caller":"[email protected]/clientconn.go:106","msg":"scheme \"\" not registered, fallback to default scheme","system":"grpc","grpc_log":true}
{"level":"info","ts":1595429173.692434,"caller":"passthrough/passthrough.go:48","msg":"ccResolverWrapper: sending update to cc: {[{collector-svc:14250  <nil> 0 <nil>}] <nil> <nil>}","system":"grpc","grpc_log":true}
{"level":"info","ts":1595429173.6924582,"caller":"[email protected]/clientconn.go:948","msg":"ClientConn switching balancer to \"round_robin\"","system":"grpc","grpc_log":true}
{"level":"info","ts":1595429173.6941726,"caller":"command-line-arguments/main.go:78","msg":"Starting agent"}
{"level":"info","ts":1595429173.6942337,"caller":"healthcheck/handler.go:128","msg":"Health Check state change","status":"ready"}
{"level":"info","ts":1595429173.6956027,"caller":"app/agent.go:69","msg":"Starting jaeger-agent HTTP server","http-port":5778}
{"level":"info","ts":1595429173.7920358,"caller":"base/balancer.go:196","msg":"roundrobinPicker: newPicker called with info: {map[0xc00020e890:{{collector-svc:14250  <nil> 0 <nil>}}]}","system":"grpc","grpc_log":true}
0
0
0
0
0
0
0
0

jaeger_agent_collector_proxy_total{endpoint="sampling",protocol="grpc",result="err"} 0
jaeger_agent_collector_proxy_total{endpoint="sampling",protocol="grpc",result="ok"} 8

To Reproduce
Steps to reproduce the behavior:

1. Deploy Jaeger agent container.
2. Open the log stream.
3. Create a local port forwarding and curl that specific agent with curl -v http://localhost:5778/sampling\?service\=dummy
4. A new line in the log should appear with the value 0.

Expected behavior
This log does not show up because it has no value. If the log has a value for some reason, it should be displayed with debug level only and formatted properly.

Version (please complete the following information):

• OS: Linux
• Jaeger version: 1.8
• Deployment: Kubernetes

What troubleshooting steps did you try?
I tried several requests like http://localhost:14271/metrics and http://localhost:5778/baggageRestrictions but these dont cause issues. When I execute curl http://localhost:5778/sampling, I get
'service' parameter must be provided once and in that case there is no additional 0. That means the "log" happens after https://github.com/jaegertracing/jaeger/blob/1803e05e5a5f261f788935035aa5dabb99bcbbea/pkg/clientcfg/clientcfghttp/handler.go#L129.

Additional context
This is not causing any issues, it is just very annoying. I tried to find in the code where/why this is sent to the standard output. Since it is not a log, it is quite hard to find. Could it be the exit code of a process ?

[yurishkuro]

hm, doesn't seem to happen in all-in-one.

[jpkrohling]

I'm also not able to reproduce this with the regular Jaeger 1.18 images:

$ podman pod create --name jaeger -p 5778 -p 14271
$ podman container create --pod jaeger --name jaeger-collector -e SPAN_STORAGE_TYPE=memory -p 14250 jaegertracing/jaeger-collector:1.18
$ podman container create --pod jaeger --name jaeger-agent -p 5778 -p 14271 jaegertracing/jaeger-agent:1.18 --reporter.grpc.host-port=localhost:14250
$ podman pod start jaeger
$ curl localhost:5778/sampling?service=myapp
$ podman logs jaeger-agent

This is all I see in the logs, no matter how many times I run the curl command:

$ podman logs jaeger-agent
2020/07/23 07:53:42 maxprocs: Leaving GOMAXPROCS=12: CPU quota undefined
{"level":"info","ts":1595490822.123359,"caller":"flags/service.go:116","msg":"Mounting metrics handler on admin server","route":"/metrics"}
{"level":"info","ts":1595490822.1236496,"caller":"flags/admin.go:120","msg":"Mounting health check on admin server","route":"/"}
{"level":"info","ts":1595490822.1236842,"caller":"flags/admin.go:126","msg":"Starting admin HTTP server","http-addr":":14271"}
{"level":"info","ts":1595490822.1236944,"caller":"flags/admin.go:112","msg":"Admin server started","http.host-port":"[::]:14271","health-status":"unavailable"}
{"level":"info","ts":1595490822.124169,"caller":"grpc/builder.go:66","msg":"Agent requested insecure grpc connection to collector(s)"}
{"level":"info","ts":1595490822.1242957,"caller":"[email protected]/clientconn.go:106","msg":"parsed scheme: \"\"","system":"grpc","grpc_log":true}
{"level":"info","ts":1595490822.1243272,"caller":"[email protected]/clientconn.go:106","msg":"scheme \"\" not registered, fallback to default scheme","system":"grpc","grpc_log":true}
{"level":"info","ts":1595490822.124338,"caller":"passthrough/passthrough.go:48","msg":"ccResolverWrapper: sending update to cc: {[{localhost:14250  <nil> 0 <nil>}] <nil> <nil>}","system":"grpc","grpc_log":true}
{"level":"info","ts":1595490822.1243806,"caller":"[email protected]/clientconn.go:948","msg":"ClientConn switching balancer to \"round_robin\"","system":"grpc","grpc_log":true}
{"level":"info","ts":1595490822.1255236,"caller":"command-line-arguments/main.go:78","msg":"Starting agent"}
{"level":"info","ts":1595490822.1255527,"caller":"healthcheck/handler.go:128","msg":"Health Check state change","status":"ready"}
{"level":"info","ts":1595490822.1256187,"caller":"app/agent.go:69","msg":"Starting jaeger-agent HTTP server","http-port":5778}
{"level":"info","ts":1595490822.1407452,"caller":"base/balancer.go:196","msg":"roundrobinPicker: newPicker called with info: {map[0xc0002581c0:{{localhost:14250  <nil> 0 <nil>}}]}","system":"grpc","grpc_log":true}

$ curl -s localhost:14271/metrics  | grep 'jaeger_agent_collector_proxy_total{endpoint="sampling"'
jaeger_agent_collector_proxy_total{endpoint="sampling",protocol="grpc",result="err"} 0
jaeger_agent_collector_proxy_total{endpoint="sampling",protocol="grpc",result="ok"} 10

[agaudreault-jive]

Alright so I went a little bit further in my investigation and discovered that the problem only happens when there is at least one item in operation_strategies of the sampling configuration 😅

I was able to reproduce locally with Docker for Mac.

1. Create a sampling strategy file strategies.json with

{
  "service_strategies": [],
  "default_strategy": {
    "type": "probabilistic",
    "param": 1,
    "operation_strategies": [
      {
        "operation": "/test",
        "type": "probabilistic",
        "param": 0.0
      }
    ]
  }
}

1. Run docker run -p 14250:14250 -v strategies.json:/etc/sampling/dev/config -e SAMPLING_STRATEGIES_RELOAD_INTERVAL="1m" -e SPAN_STORAGE_TYPE=memory -e SAMPLING_STRATEGIES_FILE="/etc/sampling/dev/config" jaegertracing/jaeger-collector:1.18

2. Run docker run -p 5778:5778 -p 14271:14271 -e REPORTER_GRPC_HOST_PORT="host.docker.internal:14250" jaegertracing/jaeger-agent:1.18

3. Run curl -v localhost:5778/sampling?service=dummy

If you remove all operation_strategies from the file (either removing the property or setting []), then restart both collector and agent, the problem does not happen anymore. 🤔 Looking at https://www.jaegertracing.io/docs/1.18/sampling/, the sampling file seems valid an no error are thrown in the collector when it is reloaded.

[agaudreault-jive]

@jpkrohling where you able to reproduce with these steps ?

[jpkrohling]

Yup, got it as well. Placing the config you provided on /tmp/sampling.json, this is enough to reproduce:

$ SPAN_STORAGE_TYPE=memory go run ./cmd/all-in-one --sampling.strategies-file /tmp/sampling.json 
$ curl -s localhost:5778/sampling?service=dummy

And the following is shown in the stdout for Jaeger:

{"level":"info","ts":1597072410.5400405,"caller":"app/server.go:240","msg":"Starting CMUX server","port":16686,"addr":":16686"}
{"level":"info","ts":1597072410.5400412,"caller":"app/server.go:215","msg":"Starting HTTP server","port":16686,"addr":":16686"}
{"level":"info","ts":1597072410.5400488,"caller":"app/server.go:230","msg":"Starting GRPC server","port":16686,"addr":":16686"}
0