Querier: Queries hang forever after Ingester running several hours later sometimes

[mizeng]

Describe the bug
After the Loki Ingesters running for sometime, Log Query through Querier will hang for ever. However label query works at the same time.

To Reproduce
Steps to reproduce the behavior:

1. Started loki in separate mode, keep ingesting logs and let Ingester run for several hours.
2. Query: ./logcli --addr="http://querier:3100" --username="admin" --password="admin" labels works.
3. Query: ./logcli --addr="http://querier:3100" --username="admin" --password="admin" query '{threadName="LokiSink0"}' --since=10m hangs forever.
4. Recreate the Ingester pod, then the query works again.

➜  loki git:(master) ✗ ./logcli --addr="http://querier:3100" --username="admin" --password="admin" query '{threadName="LokiSink0"}' --since=10m
2019/06/20 09:24:41 http://querier:3100/api/prom/query?query=%7BthreadName%3D%22LokiSink0%22%7D&limit=30&start=1560993281045092000&end=1560993881045092000&direction=BACKWARD&regexp=
2019/06/20 09:24:41 Common labels: {hostname="xxx", namespace="performanceTest", threadName="LokiSink0"}
2019-06-20T01:24:41Z {} Thu Jun 20 01:24:41 UTC 2019 This is performance test, thread=1, schedule=1000, logNum=10000

Expected behavior
Querier should not hang.

Environment:

• Infrastructure: Kubernetes

Screenshots, promtail config, or terminal output
Env: 1 Distributor, 1 Ingester, 1 table-manger, 1 querier
Store:
Index Store: BoltDB in CephFS,
Chunk Store: FileSystem in CephFS

The Ingester is with 20GB max memory, and only uses about 8GB now.

Logs from Querier for above hang query:

level=debug ts=2019-06-20T01:09:14.433633657Z caller=http.go:114 request="&QueryRequest{Query:{threadName=\"LokiSink0\"},Limit:30,Start:2019-06-20 00:59:14.146264 +0000 UTC,End:2019-06-20 01:09:14.146264 +0000 UTC,Direction:BACKWARD,Regex:,}"
ts=2019-06-20T01:09:14.434250471Z caller=spanlogger.go:37 org_id=fake trace_id=73ceef22e1a03e75 method=SeriesStore.GetChunkRefs level=debug metric=logs
ts=2019-06-20T01:09:14.434300888Z caller=spanlogger.go:37 org_id=fake trace_id=73ceef22e1a03e75 method=SeriesStore.lookupSeriesByMetricNameMatchers level=debug metricName=logs matchers=1
ts=2019-06-20T01:09:14.434354001Z caller=spanlogger.go:37 org_id=fake trace_id=73ceef22e1a03e75 method=SeriesStore.lookupSeriesByMetricNameMatcher level=debug metricName=logs matcher="threadName=\"LokiSink0\""
ts=2019-06-20T01:09:14.434400838Z caller=spanlogger.go:37 org_id=fake trace_id=73ceef22e1a03e75 method=SeriesStore.lookupSeriesByMetricNameMatcher level=debug queries=1
ts=2019-06-20T01:09:14.434461812Z caller=spanlogger.go:37 org_id=fake trace_id=73ceef22e1a03e75 method=cachingIndexClient.cacheFetch level=debug hits=0 misses=1

Logs for Querier for above same query but not hang

level=debug ts=2019-06-20T01:40:13.733006595Z caller=http.go:114 request="&QueryRequest{Query:{threadName=\"LokiSink0\"},Limit:30,Start:2019-06-20 01:35:13.447327 +0000 UTC,End:2019-06-20 01:40:13.447327 +0000 UTC,Direction:BACKWARD,Regex:,}"
ts=2019-06-20T01:40:13.764794175Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.GetChunkRefs level=debug metric=logs
ts=2019-06-20T01:40:13.764880813Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.lookupSeriesByMetricNameMatchers level=debug metricName=logs matchers=1
ts=2019-06-20T01:40:13.765321343Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.lookupSeriesByMetricNameMatcher level=debug metricName=logs matcher="threadName=\"LokiSink0\""
ts=2019-06-20T01:40:13.765426524Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.lookupSeriesByMetricNameMatcher level=debug queries=1
ts=2019-06-20T01:40:13.765464052Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=cachingIndexClient.cacheFetch level=debug hits=0 misses=1
ts=2019-06-20T01:40:13.765596379Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.lookupSeriesByMetricNameMatcher level=debug entries=3
ts=2019-06-20T01:40:13.765628761Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.lookupSeriesByMetricNameMatcher level=debug ids=3
ts=2019-06-20T01:40:13.765646999Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.lookupSeriesByMetricNameMatchers level=debug msg="post intersection" ids=3
ts=2019-06-20T01:40:13.765660083Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.GetChunkRefs level=debug series-ids=3
ts=2019-06-20T01:40:13.765678606Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.lookupChunksBySeries level=debug seriesIDs=3
ts=2019-06-20T01:40:13.765696522Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.lookupChunksBySeries level=debug queries=3
ts=2019-06-20T01:40:13.765754328Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=cachingIndexClient.cacheFetch level=debug hits=0 misses=3
ts=2019-06-20T01:40:13.789312745Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.lookupChunksBySeries level=debug entries=0
ts=2019-06-20T01:40:13.789402637Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.GetChunkRefs level=debug chunk-ids=0
ts=2019-06-20T01:40:13.789417386Z caller=spanlogger.go:37 org_id=fake trace_id=649671e1a0b78f48 method=SeriesStore.GetChunkRefs level=debug chunks-post-filtering=0
level=debug ts=2019-06-20T01:40:29.336996744Z caller=logging.go:44 traceID=649671e1a0b78f48 msg="GET /api/prom/query?query=%7BthreadName%3D%22LokiSink0%22%7D&limit=30&start=1560994513447327000&end=1560994813447327000&direction=BACKWARD&regexp= (200) 15.604040415s"

[mizeng]

Looks like hang in below code snippet of chunk_store.go:

func (c *store) lookupEntriesByQueries(ctx context.Context, queries []IndexQuery) ([]IndexEntry, error) {
	var lock sync.Mutex
	var entries []IndexEntry
	err := c.index.QueryPages(ctx, queries, func(query IndexQuery, resp ReadBatch) bool {
		iter := resp.Iterator()
		lock.Lock()
		for iter.Next() {
			entries = append(entries, IndexEntry{
				TableName:  query.TableName,
				HashValue:  query.HashValue,
				RangeValue: iter.RangeValue(),
				Value:      iter.Value(),
			})
		}
		lock.Unlock()
		return true
	})
	if err != nil {
		level.Error(util.WithContext(ctx, util.Logger)).Log("msg", "error querying storage", "err", err)
	}
	return entries, err
}

I didn't see any go routine usage here, why use mutex Lock?

[mizeng]

Narrow down hang to below code snippet of caching_index_client.go:

err = s.IndexClient.QueryPages(ctx, cacheableMissed, func(cacheableQuery chunk.IndexQuery, r chunk.ReadBatch) bool {
		resultsMtx.Lock()
		defer resultsMtx.Unlock()
		key := queryKey(cacheableQuery)
		existing := results[key]
		for iter := r.Iterator(); iter.Next(); {
			existing.Entries = append(existing.Entries, Entry{Column: iter.RangeValue(), Value: iter.Value()})
		}
		results[key] = existing
		return true
	})

Going on, it led me to below code snippet of boltdb_index_client.go.

func (b *boltIndexClient) QueryPages(ctx context.Context, queries []chunk.IndexQuery, callback func(chunk.IndexQuery, chunk.ReadBatch) (shouldContinue bool)) error {
	return chunk_util.DoParallelQueries(ctx, b.query, queries, callback)
}

Then it led me to b.query, the below code snippet of boltdb_index_client.go.

func (b *boltIndexClient) query(ctx context.Context, query chunk.IndexQuery, callback func(chunk.ReadBatch) (shouldContinue bool)) error {
	db, err := b.getDB(query.TableName)

So narrow down to getDB of boltdb hang.

[mizeng]

Going on, I've restarted querier several times, and find it has below pattern.

1. When the Querier just started, and serve the first query. It hangs on db, err := bbolt.Open(path.Join(b.cfg.Directory, name), 0666, nil) inside getDB function mentioned above.
2. Inside the bblot.Open, it hangs on if err := flock(db, !db.readOnly, options.Timeout); err != nil {
   , the flock function.
3. Inside flock, it hangs on below for loop.

for {
		// Attempt to obtain an exclusive lock.
		err := syscall.Flock(int(fd), flag)
		if err == nil {
			return nil
		} else if err != syscall.EWOULDBLOCK {
			return err
		}

		// If we timed out then return an error.
		if timeout != 0 && time.Since(t) > timeout-flockRetryTimeout {
			return ErrTimeout
		}

		// Wait for a bit and try again.
		time.Sleep(flockRetryTimeout)
	}

4. Normally there's no error for err := syscall.Flock(int(fd), flag). However it's EAGAIN here (I don't know why), and no timeout specified. So infinitive loop here.
5. Then if I force quit the query command line of "logcli", execute the same query again. The Querier hangs on can not get RLock. This is obviously since the first query served in Querier has not release the RLock.

func (b *boltIndexClient) getDB(name string) (*bbolt.DB, error) {
	b.dbsMtx.RLock()

6. However I still don't know why the Querier start to fail into this issue in the first time. From my local testing, I can even reproduce in my local MAC with seperate mode deployment of Loki. Wait some hours, then it may appear.
7. To recover, just restart Ingester. Then err := syscall.Flock(int(fd), flag) shows no error. Another question came, why boltdb client can not get flock related to Ingester? since restarting Ingester resolve the issue.

[mizeng]

@Kuqd could you help to engage some expert who is familiar with boltdb client to take a look? I've narrowed down the issue.

[mizeng]

To avoid fail into dead loop, filed cortexproject/cortex#1471 to fix.

Remaining: Why Ingester caused Querier can not get boldDB client?

I'm guessing both Ingester and Querier are using db, err := bbolt.Open(path.Join(b.cfg.Directory, name), 0666, nil) to use a read-write lock to get BoltDB instance by default. Then somehow Ingester lock the BoltDB file and then Querier failed to get BoltDB instance due to some lock issue.
Since mentioned in https://github.com/boltdb/bolt#read-only-mode, seems Querier would better use a read lock to get a BoltDB.

Update:
From official README of BoltDB, it said

Please note that Bolt obtains a file lock on the data file so multiple processes cannot open the same database at the same time. Opening an already open Bolt database will cause it to hang until the other process closes it. To prevent an indefinite wait you can pass a timeout option to the Open() function.

[mizeng]

So summary as below:

1. Querier hang due to Ingester's already opened the Bolt DB at the first time.
2. Querier hang due to itself can not get the RLock: b.dbsMtx.RLock() for all of the next queries.

Resolution:

1. Let BoltDB client has timeout options to avoid above No.2 hang issue. Already filed PR add options for boltdb_index_client to avoid dead loop cortexproject/cortex#1471.
2. If not deploy Loki with all-in-one process mode, avoid using BoltDB since it will have file lock issue.