index out of range panic when serving /federation request

[beorn7]

This is v2.0.0-rc.2. I haven't seen it in any previously built Prom2 binaries, including the one built from commit 48b303b .

On one of our servers, I see this very soon after startup, even from an empty storage:

2017-10-26_13:08:15.09779 level=info ts=2017-10-26T13:08:15.097656479Z caller=main.go:215 msg="Starting Prometheus" version="(version=2.0.0-rc.2, branch=HEAD, revision=ce63a5a8557bb33e2030a7756c58fd773736b592)"
2017-10-26_13:08:15.09782 level=info ts=2017-10-26T13:08:15.097744819Z caller=main.go:216 build_context="(go=go1.9.1, user=root@a6d2e4a7b8da, date=20171025-18:42:54)"
2017-10-26_13:08:15.09783 level=info ts=2017-10-26T13:08:15.097774128Z caller=main.go:217 host_details="(Linux 4.4.10+soundcloud #1 SMP Thu Jun 16 15:17:20 UTC 2016 x86_64 <ELIDED> (none))"
2017-10-26_13:08:15.10152 level=info ts=2017-10-26T13:08:15.10139469Z caller=web.go:380 component=web msg="Start listening for connections" address=0.0.0.0:9090
2017-10-26_13:08:15.10154 level=info ts=2017-10-26T13:08:15.101376031Z caller=main.go:314 msg="Starting TSDB"
2017-10-26_13:08:15.10155 level=info ts=2017-10-26T13:08:15.101451654Z caller=targetmanager.go:69 component="target manager" msg="Starting target manager..."
2017-10-26_13:08:15.11311 level=info ts=2017-10-26T13:08:15.112990937Z caller=main.go:326 msg="TSDB started"
2017-10-26_13:08:15.11313 level=info ts=2017-10-26T13:08:15.113070546Z caller=main.go:394 msg="Loading configuration file" filename=/data1/prometheus/prometheus.yml
2017-10-26_13:08:15.16121 level=info ts=2017-10-26T13:08:15.161119219Z caller=main.go:371 msg="Server is ready to receive requests."
2017-10-26_13:08:19.86974 level=error ts=2017-10-26T13:08:19.869656984Z caller=stdlib.go:89 component=web caller="http: panic serving <ELIDED>:55935" msg="runtime error: index out of range"
2017-10-26_13:08:24.67130 panic: runtime error: index out of range
2017-10-26_13:08:24.67135 
2017-10-26_13:08:24.67135 goroutine 856 [running]:
2017-10-26_13:08:24.67137 github.com/prometheus/prometheus/storage/tsdb.adapter.StartTime(0xc4203e3d40, 0x6ddd00, 0x0, 0x0, 0x0)
2017-10-26_13:08:24.67138       /go/src/github.com/prometheus/prometheus/storage/tsdb/tsdb.go:194 +0x552
2017-10-26_13:08:24.67138 github.com/prometheus/prometheus/storage/tsdb.(*ReadyStorage).StartTime(0xc4203a6000, 0x196d000, 0xc4817e1101, 0x297c098)
2017-10-26_13:08:24.67139       /go/src/github.com/prometheus/prometheus/storage/tsdb/tsdb.go:68 +0x4e
2017-10-26_13:08:24.67140 github.com/prometheus/prometheus/storage/tsdb.(*ReadyStorage).StartTime-fm(0x196d000, 0x0, 0x0)
2017-10-26_13:08:24.67140       /go/src/github.com/prometheus/prometheus/cmd/prometheus/main.go:227 +0x2a
2017-10-26_13:08:24.67141 github.com/prometheus/prometheus/storage/remote.(*Storage).Querier(0xc42054f260, 0x288dc00, 0xc43682b020, 0x15f58c7b7fb, 0x15f58cc4bdb, 0x0, 0x0, 0x0, 0x0)
2017-10-26_13:08:24.67141       /go/src/github.com/prometheus/prometheus/storage/remote/read.go:33 +0x10a
2017-10-26_13:08:24.67141 github.com/prometheus/prometheus/storage.(*fanout).Querier(0xc42054ce80, 0x288dc00, 0xc43682b020, 0x15f58c7b7fb, 0x15f58cc4bdb, 0xffffffbc685b4077, 0x2958e80, 0xa311bd6915280956, 0x10)
2017-10-26_13:08:24.67142       /go/src/github.com/prometheus/prometheus/storage/fanout.go:79 +0x1ed
2017-10-26_13:08:24.67142 github.com/prometheus/prometheus/promql.(*Engine).populateIterators(0xc420309140, 0x288dc00, 0xc43682b020, 0xc46ab846e0, 0x411bbc, 0xc420200540, 0xc4817e13e8, 0x43c81c)
2017-10-26_13:08:24.67142       /go/src/github.com/prometheus/prometheus/promql/engine.go:510 +0x2f5
2017-10-26_13:08:24.67143 github.com/prometheus/prometheus/promql.(*Engine).execEvalStmt(0xc420309140, 0x288dc00, 0xc43682b020, 0xc467370800, 0xc46ab846e0, 0x0, 0x0, 0x0, 0x0)
2017-10-26_13:08:24.67144       /go/src/github.com/prometheus/prometheus/promql/engine.go:361 +0xf5
2017-10-26_13:08:24.67144 github.com/prometheus/prometheus/promql.(*Engine).exec(0xc420309140, 0x288dc00, 0xc43682b020, 0xc467370800, 0x0, 0x0, 0x0, 0x0)
2017-10-26_13:08:24.67145       /go/src/github.com/prometheus/prometheus/promql/engine.go:341 +0x317
2017-10-26_13:08:24.67145 github.com/prometheus/prometheus/promql.(*query).Exec(0xc467370800, 0x288db80, 0xc42054d100, 0xbe74957227c9ca22)
2017-10-26_13:08:24.67145       /go/src/github.com/prometheus/prometheus/promql/engine.go:179 +0xb8
2017-10-26_13:08:24.67146 github.com/prometheus/prometheus/rules.RecordingRule.Eval(0xc420bb84e0, 0x26, 0x2883300, 0xc420d9e960, 0x297c098, 0x0, 0x0, 0x288db80, 0xc42054d100, 0xbe74957227c9ca22, ...)
2017-10-26_13:08:24.67147       /go/src/github.com/prometheus/prometheus/rules/recording.go:60 +0xf7
2017-10-26_13:08:24.67147 github.com/prometheus/prometheus/rules.(*RecordingRule).Eval(0xc420244640, 0x288db80, 0xc42054d100, 0xbe74957227c9ca22, 0x241bff877, 0x2958e80, 0xc420309140, 0xc420302a00, 0xc4215a8f60, 0x7f88eb1fac10, ...)
2017-10-26_13:08:24.67150       <autogenerated>:1 +0xd0
2017-10-26_13:08:24.67151 github.com/prometheus/prometheus/rules.(*Group).Eval.func1(0x1ba9242, 0x9, 0xc420283300, 0xbe74957227c9ca22, 0x241bff877, 0x2958e80, 0x0, 0x288df00, 0xc420244640)
2017-10-26_13:08:24.67153       /go/src/github.com/prometheus/prometheus/rules/manager.go:307 +0x194
2017-10-26_13:08:24.67154 github.com/prometheus/prometheus/rules.(*Group).Eval(0xc420283300, 0xbe74957227c9ca22, 0x241bff877, 0x2958e80)
2017-10-26_13:08:24.67155       /go/src/github.com/prometheus/prometheus/rules/manager.go:375 +0xbf
2017-10-26_13:08:24.67156 github.com/prometheus/prometheus/rules.(*Group).run.func1()
2017-10-26_13:08:24.67156       /go/src/github.com/prometheus/prometheus/rules/manager.go:182 +0x81
2017-10-26_13:08:24.67157 github.com/prometheus/prometheus/rules.(*Group).run(0xc420283300)
2017-10-26_13:08:24.67158       /go/src/github.com/prometheus/prometheus/rules/manager.go:187 +0x1b9
2017-10-26_13:08:24.67158 github.com/prometheus/prometheus/rules.(*Manager).ApplyConfig.func1.1(0xc42054d140, 0xc420283300)
2017-10-26_13:08:24.67159       /go/src/github.com/prometheus/prometheus/rules/manager.go:510 +0x46
2017-10-26_13:08:24.67160 created by github.com/prometheus/prometheus/rules.(*Manager).ApplyConfig.func1
2017-10-26_13:08:24.67161       /go/src/github.com/prometheus/prometheus/rules/manager.go:505 +0x56

The request it is serving is a federation request (i.e. hitting the /federation endpoint of the crashing Prometheus server).

If the server is restarted after the panic, the log looks like this (only subtly different):

2017-10-26_13:15:27.17703 level=info ts=2017-10-26T13:15:27.176906266Z caller=main.go:215 msg="Starting Prometheus" version="(version=2.0.0-rc.2, branch=HEAD, revision=ce63a5a8557bb33e2030a7756c58fd773736b592)"
2017-10-26_13:15:27.17705 level=info ts=2017-10-26T13:15:27.176990488Z caller=main.go:216 build_context="(go=go1.9.1, user=root@a6d2e4a7b8da, date=20171025-18:42:54)"
2017-10-26_13:15:27.17707 level=info ts=2017-10-26T13:15:27.177023474Z caller=main.go:217 host_details="(Linux 4.4.10+soundcloud #1 SMP Thu Jun 16 15:17:20 UTC 2016 x86_64 <ELIDED> (none))"
2017-10-26_13:15:27.18017 level=info ts=2017-10-26T13:15:27.180016499Z caller=main.go:314 msg="Starting TSDB"
2017-10-26_13:15:27.18019 level=info ts=2017-10-26T13:15:27.180070554Z caller=web.go:380 component=web msg="Start listening for connections" address=0.0.0.0:9090
2017-10-26_13:15:27.18020 level=info ts=2017-10-26T13:15:27.18006715Z caller=targetmanager.go:69 component="target manager" msg="Starting target manager..."
2017-10-26_13:16:00.58344 level=error ts=2017-10-26T13:16:00.583209146Z caller=wal.go:273 component=tsdb msg="WAL corruption detected; truncating" err="unexpected CRC32 checksum d4b5853c, want 0" file=/data1/prometheus/storage/wal/000013 pos=62974722
2017-10-26_13:16:01.41976 level=info ts=2017-10-26T13:16:01.419684018Z caller=main.go:326 msg="TSDB started"
2017-10-26_13:16:01.41979 level=info ts=2017-10-26T13:16:01.419763661Z caller=main.go:394 msg="Loading configuration file" filename=/data1/prometheus/prometheus.yml
2017-10-26_13:16:01.45141 level=info ts=2017-10-26T13:16:01.451305744Z caller=main.go:371 msg="Server is ready to receive requests."
2017-10-26_13:16:16.68895 panic: runtime error: index out of range
2017-10-26_13:16:16.68898 
2017-10-26_13:16:16.68899 goroutine 1610 [running]:
2017-10-26_13:16:16.68899 github.com/prometheus/prometheus/storage/tsdb.adapter.StartTime(0xc420530c30, 0x6ddd00, 0x0, 0x0, 0x0)
2017-10-26_13:16:16.68900       /go/src/github.com/prometheus/prometheus/storage/tsdb/tsdb.go:194 +0x552
2017-10-26_13:16:16.68900 github.com/prometheus/prometheus/storage/tsdb.(*ReadyStorage).StartTime(0xc420141e40, 0x196d000, 0xc5b18f6f01, 0x297c098)
2017-10-26_13:16:16.68900       /go/src/github.com/prometheus/prometheus/storage/tsdb/tsdb.go:68 +0x4e
2017-10-26_13:16:16.68901 github.com/prometheus/prometheus/storage/tsdb.(*ReadyStorage).StartTime-fm(0x196d000, 0x0, 0x0)
2017-10-26_13:16:16.68901       /go/src/github.com/prometheus/prometheus/cmd/prometheus/main.go:227 +0x2a
2017-10-26_13:16:16.68902 github.com/prometheus/prometheus/storage/remote.(*Storage).Querier(0xc420147420, 0x288dc00, 0xc5dbf00a80, 0x15f58cee251, 0x15f58d37631, 0x0, 0x0, 0x0, 0x0)
2017-10-26_13:16:16.68902       /go/src/github.com/prometheus/prometheus/storage/remote/read.go:33 +0x10a
2017-10-26_13:16:16.68904 github.com/prometheus/prometheus/storage.(*fanout).Querier(0xc420185a00, 0x288dc00, 0xc5dbf00a80, 0x15f58cee251, 0x15f58d37631, 0xffffffc5233835c7, 0x2958e80, 0xc7631d591f557103, 0x10)
2017-10-26_13:16:16.68911       /go/src/github.com/prometheus/prometheus/storage/fanout.go:79 +0x1ed
2017-10-26_13:16:16.68911 github.com/prometheus/prometheus/promql.(*Engine).populateIterators(0xc4201a8660, 0x288dc00, 0xc5dbf00a80, 0xc5e81fea00, 0x411bbc, 0xc4201fa600, 0xc5b18f72b8, 0x43c81c)
2017-10-26_13:16:16.68918       /go/src/github.com/prometheus/prometheus/promql/engine.go:510 +0x2f5
2017-10-26_13:16:16.68920 github.com/prometheus/prometheus/promql.(*Engine).execEvalStmt(0xc4201a8660, 0x288dc00, 0xc5dbf00a80, 0xc5dc01c280, 0xc5e81fea00, 0x0, 0x0, 0x0, 0x0)
2017-10-26_13:16:16.68920       /go/src/github.com/prometheus/prometheus/promql/engine.go:361 +0xf5
2017-10-26_13:16:16.68921 github.com/prometheus/prometheus/promql.(*Engine).exec(0xc4201a8660, 0x288dc00, 0xc5dbf00a80, 0xc5dc01c280, 0x0, 0x0, 0x0, 0x0)
2017-10-26_13:16:16.68922       /go/src/github.com/prometheus/prometheus/promql/engine.go:341 +0x317
2017-10-26_13:16:16.68923 github.com/prometheus/prometheus/promql.(*query).Exec(0xc5dc01c280, 0x288db80, 0xc420185c40, 0xbe7495e78f5f6905)
2017-10-26_13:16:16.68923       /go/src/github.com/prometheus/prometheus/promql/engine.go:179 +0xb8
2017-10-26_13:16:16.68924 github.com/prometheus/prometheus/rules.(*AlertingRule).Eval(0xc5b14de300, 0x288db80, 0xc420185c40, 0xbe7495e78f5f6905, 0xafc9cedc7, 0x2958e80, 0xc4201a8660, 0xc4201eab80, 0x0, 0x0, ...)
2017-10-26_13:16:16.68925       /go/src/github.com/prometheus/prometheus/rules/alerting.go:163 +0x133
2017-10-26_13:16:16.68925 github.com/prometheus/prometheus/rules.(*Group).Eval.func1(0x1ba7918, 0x8, 0xc5b14de400, 0xbe7495e78f5f6905, 0xafc9cedc7, 0x2958e80, 0x7, 0x288dec0, 0xc5b14de300)
2017-10-26_13:16:16.68926       /go/src/github.com/prometheus/prometheus/rules/manager.go:307 +0x194
2017-10-26_13:16:16.68927 github.com/prometheus/prometheus/rules.(*Group).Eval(0xc5b14de400, 0xbe7495e78f5f6905, 0xafc9cedc7, 0x2958e80)
2017-10-26_13:16:16.68927       /go/src/github.com/prometheus/prometheus/rules/manager.go:375 +0xbf
2017-10-26_13:16:16.68928 github.com/prometheus/prometheus/rules.(*Group).run.func1()
2017-10-26_13:16:16.68928       /go/src/github.com/prometheus/prometheus/rules/manager.go:182 +0x81
2017-10-26_13:16:16.68929 github.com/prometheus/prometheus/rules.(*Group).run(0xc5b14de400)
2017-10-26_13:16:16.68929       /go/src/github.com/prometheus/prometheus/rules/manager.go:187 +0x1b9
2017-10-26_13:16:16.68930 github.com/prometheus/prometheus/rules.(*Manager).ApplyConfig.func1.1(0xc420185c80, 0xc5b14de400)
2017-10-26_13:16:16.68930       /go/src/github.com/prometheus/prometheus/rules/manager.go:510 +0x46
2017-10-26_13:16:16.68932 created by github.com/prometheus/prometheus/rules.(*Manager).ApplyConfig.func1
2017-10-26_13:16:16.68932       /go/src/github.com/prometheus/prometheus/rules/manager.go:505 +0x56

[juliusv]

Isn't that just the same panic as in #3340? The revision at which you're running Prometheus doesn't include the fix (#3344) yet.

[beorn7]

I see. Wasn't aware that there were bugfixes post-rc.2.

Building from master now.

[fabxc]

Oh, damn. I missed that one when pushing rc.2, sorry.

[beorn7]

OK, that worked…

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.