Jaeger-operator: jaeger query repeating log lines

[samcrutt9900]

The jaeger query has been deployed via the operator.
Version is 1.16.0
Platform: openshift 3.11

The logs for the query pod are being filled up with the following log line:
{"level":"info","ts":1582817795.8145893,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
This line is being logged every 0.5 second or so.

[jkandasa]

some info relevant to this issue: https://github.com/jaegertracing/jaeger-operator/issues/533#issuecomment-517216871

[jpkrohling]

@samcrutt9900, unfortunately, it is quite possible that this code doesn't work properly in OpenShift 3.11. Would you be willing to test on a newer cluster, like OpenShift 4.3?

If you are seeing a reloading UI config there every 0.5 second, then we need to investigate and address that.

[jkandasa]

@jpkrohling Just now I checked our test logs. I see this issue on OCP 4.3. But it is not every 0.5 seconds.

Version data:

jaeger-query: 1.16.0
Server Version: 4.3.1
Kubernetes Version: v1.16.2

this log captured for 15 minutes log:

{"level":"info","ts":1582209567.028163,"caller":"flags/service.go:115","msg":"Mounting metrics handler on admin server","route":"/metrics"}
{"level":"info","ts":1582209567.0287373,"caller":"flags/admin.go:108","msg":"Mounting health check on admin server","route":"/"}
{"level":"info","ts":1582209567.0288222,"caller":"flags/admin.go:114","msg":"Starting admin HTTP server","http-port":16687}
{"level":"info","ts":1582209567.0288553,"caller":"flags/admin.go:100","msg":"Admin server started","http-port":16687,"health-status":"unavailable"}
{"level":"info","ts":1582209567.1204472,"caller":"config/config.go:172","msg":"Elasticsearch detected","version":5}
{"level":"info","ts":1582209567.1219795,"caller":"app/static_handler.go:176","msg":"watching","file":"/etc/config/ui.json"}
{"level":"info","ts":1582209567.1220148,"caller":"app/static_handler.go:184","msg":"watching","dir":"/etc/config"}
{"level":"info","ts":1582209567.1222315,"caller":"healthcheck/handler.go:128","msg":"Health Check state change","status":"ready"}
{"level":"info","ts":1582209567.1222522,"caller":"app/server.go:135","msg":"Starting CMUX server","port":16686}
{"level":"info","ts":1582209567.122527,"caller":"app/server.go:112","msg":"Starting HTTP server","port":16686}
{"level":"info","ts":1582209567.1225536,"caller":"app/server.go:125","msg":"Starting GRPC server","port":16686}
{"level":"info","ts":1582209570.67485,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209570.6750507,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209570.6756234,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209571.6826277,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209571.682857,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209571.6829314,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209660.541147,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209660.5419843,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209660.542112,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209722.4985597,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209722.4993293,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209722.4994016,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209804.554374,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209804.556744,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209804.5568602,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209893.5396142,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209893.5463095,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209893.5464492,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209970.5723433,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209970.5728827,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582209970.5729208,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210034.498819,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210034.4997246,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210034.499803,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210101.5289884,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210101.5299835,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210101.530103,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210171.5974598,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210171.5985246,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210171.5986428,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210232.5636551,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210232.5658648,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210232.5661654,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210315.5537915,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210315.554623,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210315.5547082,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210404.5289752,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210404.5296063,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210404.5299013,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210468.5486624,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210468.5494034,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}
{"level":"info","ts":1582210468.5495527,"caller":"app/static_handler.go:155","msg":"reloading UI config","filename":"/etc/config/ui.json"}

[jpkrohling]

I assume there's no reason for this, right? Definitely sounds like a bug.

@annanay25 I know you worked on something similar in the Jaeger side recently. Have you seen something like this?

[jkandasa]

@jpkrohling looks like it is a problem with https://github.com/fsnotify/fsnotify to watch symbolic links.

References:

• https://github.com/fsnotify/fsnotify/issues/199
• https://github.com/istio/istio/issues/7877
• https://github.com/istio/istio/pull/9370

Source code in jaeger-query: https://github.com/jaegertracing/jaeger/blob/v1.16.0/cmd/query/app/static_handler.go#L172~L180

jaeger-query ui.json on OCP cluster:

sh-4.2$ ls -alh /etc/config/
total 0
drwxrwsrwx. 3 root 1000540000 74 Feb 28 16:12 .
drwxr-xr-x. 1 root root       20 Feb 28 16:12 ..
drwxr-sr-x. 2 root 1000540000 21 Feb 28 16:12 ..2020_02_28_16_12_02.394721388
lrwxrwxrwx. 1 root root       31 Feb 28 16:12 ..data -> ..2020_02_28_16_12_02.394721388
lrwxrwxrwx. 1 root root       14 Feb 28 16:12 ui.json -> ..data/ui.json

sh-4.2$ ls -alh /etc/config/..2020_02_28_16_12_02.394721388/
total 4.0K
drwxr-sr-x. 2 root 1000540000 21 Feb 28 16:12 .
drwxrwsrwx. 3 root 1000540000 74 Feb 28 16:12 ..
-rw-r--r--. 1 root 1000540000 38 Feb 28 16:12 ui.json

Here it is a nested symbolic link.

ui.json -> ..data/ui.json (symlink)
..data -> ..2020_02_28_16_12_02.394721388 (symlink)
..2020_02_28_16_12_02.394721388/ui.json (actual file)

I wrote a small program to monitor file events on OCP cluster jaeger-query pod,

package main

import (
    "fmt"
    "path/filepath"
    "time"

    "github.com/fsnotify/fsnotify"
)

var file = "/etc/config/ui.json"

func main() {
    watcher, err := fsnotify.NewWatcher()
    if err != nil {
        panic(err)
    }
    err = watcher.Add(file)
    if err != nil {
        panic(err)
    }
    err = watcher.Add(filepath.Dir(file))
    if err != nil {
        panic(err)
    }
    for {
        select {
        case event := <-watcher.Events:
            fmt.Printf("%s, Event: %s\n", time.Now().Format("2006-01-02T15:04:05"), event.String())
        case err, ok := <-watcher.Errors:
            if !ok {
                panic(err)
            }
        }
    }
}

Result:

2020-02-28T17:12:01, Event: "/etc/config": CHMOD
2020-02-28T17:12:01, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:12:01, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:13:22, Event: "/etc/config": CHMOD
2020-02-28T17:13:22, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:13:22, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:14:29, Event: "/etc/config": CHMOD
2020-02-28T17:14:29, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:14:29, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:15:48, Event: "/etc/config": CHMOD
2020-02-28T17:15:48, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:15:48, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:16:54, Event: "/etc/config": CHMOD
2020-02-28T17:16:54, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:16:54, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:18:17, Event: "/etc/config": CHMOD
2020-02-28T17:18:17, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:18:17, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:19:31, Event: "/etc/config": CHMOD
2020-02-28T17:19:31, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:19:31, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:20:37, Event: "/etc/config": CHMOD
2020-02-28T17:20:37, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:20:37, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:22:07, Event: "/etc/config": CHMOD
2020-02-28T17:22:07, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:22:07, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:23:35, Event: "/etc/config": CHMOD
2020-02-28T17:23:35, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:23:35, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:24:48, Event: "/etc/config": CHMOD
2020-02-28T17:24:48, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:24:48, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:26:15, Event: "/etc/config": CHMOD
2020-02-28T17:26:15, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:26:15, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:27:41, Event: "/etc/config": CHMOD
2020-02-28T17:27:41, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:27:41, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:28:57, Event: "/etc/config": CHMOD
2020-02-28T17:28:57, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:28:57, Event: "/etc/config/ui.json": CHMOD
2020-02-28T17:29:59, Event: "/etc/config": CHMOD
2020-02-28T17:29:59, Event: "/etc/config": CHMOD
2020-02-28T17:29:59, Event: "/etc/config/..2020_02_28_16_12_02.394721388": CHMOD
2020-02-28T17:29:59, Event: "/etc/config/ui.json": CHMOD

[jpkrohling]

If we are really reloading the UI when no changes are happening, we might want to filter those events out. Otherwise, we can just do a better work in the logging.