Timing issues in storage test #1337

RichiH · Jan 22, 2016

This is a new machine, PC Engines Apu2b4, so I can't say for sure if local disk and RAM are OK. I do not have any indication that this is not the case and the RAM has ECC, though.

% uname -a
Linux neutronium 4.3.0-1-amd64 #1 SMP Debian 4.3.3-5 (2016-01-04) x86_64 GNU/Linux
% free -m
              total        used        free      shared  buff/cache   available
Mem:           3939          96        2216           8        1627        3806
Swap:          7628           0        7628
% go version
go version go1.5.3 linux/amd64
% git log | head -n1
commit e7b6a01888f1b552e21a9ba68553e8a843fbbef7
% make
>> formatting code
>> building binaries
 >   prometheus
 >   promtool
>> running tests
?       github.com/prometheus/prometheus/cmd/prometheus [no test files]
?       github.com/prometheus/prometheus/cmd/promtool   [no test files]
ok      github.com/prometheus/prometheus/config 0.132s
time="2016-01-22T22:05:06+01:00" level=warning msg="Alert batch larger than queue capacity, dropping 64 alerts" source="notification.go:213" 
time="2016-01-22T22:05:06+01:00" level=warning msg="Alert notification queue full, dropping 64 alerts" source="notification.go:222" 
time="2016-01-22T22:05:06+01:00" level=info msg="Stopping notification handler..." source="notification.go:275" 
panic: send on closed channel

goroutine 28 [running]:
github.com/prometheus/prometheus/notification.(*Handler).setMore(0xc82011c240)
    /home/richih/work/go/src/github.com/prometheus/prometheus/notification/notification.go:236 +0x3d
github.com/prometheus/prometheus/notification.(*Handler).Run(0xc82011c240)
    /home/richih/work/go/src/github.com/prometheus/prometheus/notification/notification.go:197 +0x53f
created by github.com/prometheus/prometheus/notification.TestHandlerFull
    /home/richih/work/go/src/github.com/prometheus/prometheus/notification/notification_test.go:183 +0x505

goroutine 1 [runnable]:
fmt.Sprintf(0x8790d0, 0x5, 0xc82010baa0, 0x1, 0x1, 0xf, 0xc820000180)
    /usr/lib/go/src/fmt/print.go:201
testing.fmtDuration(0x65fe72d, 0x0, 0x0)
    /usr/lib/go/src/testing/testing.go:255 +0x163
testing.(*T).report(0xc8200ee3f0)
    /usr/lib/go/src/testing/testing.go:509 +0x37
testing.RunTests(0x936ce0, 0xa977e0, 0x3, 0x3, 0x4ea301)
    /usr/lib/go/src/testing/testing.go:570 +0x929
testing.(*M).Run(0xc82010bee8, 0x4ea423)
    /usr/lib/go/src/testing/testing.go:494 +0x70
main.main()
    github.com/prometheus/prometheus/notification/_test/_testmain.go:58 +0x116

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
    /usr/lib/go/src/runtime/asm_amd64.s:1721 +0x1

goroutine 27 [IO wait]:
net.runtime_pollWait(0x7f5ff43edfe8, 0x72, 0xc82000e1b0)
    /usr/lib/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc82011bfe0, 0x72, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc82011bfe0, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).accept(0xc82011bf80, 0x0, 0x7f5ff43ad000, 0xc820312000)
    /usr/lib/go/src/net/fd_unix.go:408 +0x27c
net.(*TCPListener).AcceptTCP(0xc8200e4530, 0xc820012d00, 0x0, 0x0)
    /usr/lib/go/src/net/tcpsock_posix.go:254 +0x4d
net.(*TCPListener).Accept(0xc8200e4530, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/tcpsock_posix.go:264 +0x3d
net/http/httptest.(*historyListener).Accept(0xc8201c6720, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/http/httptest/server.go:48 +0x63
net/http.(*Server).Serve(0xc820199620, 0x7f5ff43ee2e8, 0xc8201c6720, 0x0, 0x0)
    /usr/lib/go/src/net/http/server.go:1887 +0xb3
created by net/http/httptest.(*Server).Start
    /usr/lib/go/src/net/http/httptest/server.go:109 +0x380

goroutine 8 [runnable]:
syscall.Syscall(0x0, 0x5, 0xc8200c5000, 0x1000, 0xffffffffffffffff, 0x0, 0xb)
    /usr/lib/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.read(0x5, 0xc8200c5000, 0x1000, 0x1000, 0x72, 0x0, 0x0)
    /usr/lib/go/src/syscall/zsyscall_linux_amd64.go:783 +0x5f
syscall.Read(0x5, 0xc8200c5000, 0x1000, 0x1000, 0xc82001d50c, 0x0, 0x0)
    /usr/lib/go/src/syscall/syscall_unix.go:160 +0x4d
net.(*netFD).Read(0xc8200d0ee0, 0xc8200c5000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/fd_unix.go:228 +0x18b
net.(*conn).Read(0xc82002c078, 0xc8200c5000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/net.go:172 +0xe4
net/http.(*liveSwitchReader).Read(0xc82009a518, 0xc8200c5000, 0x1000, 0x1000, 0xc8201a8000, 0x0, 0x0)
    /usr/lib/go/src/net/http/server.go:219 +0xa4
io.(*LimitedReader).Read(0xc82000bfe0, 0xc8200c5000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/io/io.go:427 +0xbd
bufio.(*Reader).fill(0xc820014660)
    /usr/lib/go/src/bufio/bufio.go:97 +0x1e9
bufio.(*Reader).Peek(0xc820014660, 0x4, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/bufio/bufio.go:132 +0xcc
net/http.(*conn).readRequest(0xc82009a4d0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/http/server.go:629 +0x2bb
net/http.(*conn).serve(0xc82009a4d0)
    /usr/lib/go/src/net/http/server.go:1319 +0x727
created by net/http.(*Server).Serve
    /usr/lib/go/src/net/http/server.go:1910 +0x3f6

goroutine 37 [IO wait]:
net.runtime_pollWait(0x7f5ff43ee168, 0x72, 0xc82000e1b0)
    /usr/lib/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc8201dc300, 0x72, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc8201dc300, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).Read(0xc8201dc2a0, 0xc82021d000, 0x1000, 0x1000, 0x0, 0x7f5ff6218050, 0xc82000e1b0)
    /usr/lib/go/src/net/fd_unix.go:232 +0x23a
net.(*conn).Read(0xc8201d8428, 0xc82021d000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/net.go:172 +0xe4
net/http.noteEOFReader.Read(0x7f5ff621cbd8, 0xc8201d8428, 0xc8201de1b8, 0xc82021d000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/http/transport.go:1370 +0x67
net/http.(*noteEOFReader).Read(0xc8202ffc20, 0xc82021d000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    <autogenerated>:126 +0xd0
bufio.(*Reader).fill(0xc820301740)
    /usr/lib/go/src/bufio/bufio.go:97 +0x1e9
bufio.(*Reader).Peek(0xc820301740, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/bufio/bufio.go:132 +0xcc
net/http.(*persistConn).readLoop(0xc8201de160)
    /usr/lib/go/src/net/http/transport.go:876 +0xf7
created by net/http.(*Transport).dialConn
    /usr/lib/go/src/net/http/transport.go:685 +0xc78

goroutine 38 [select]:
net/http.(*persistConn).writeLoop(0xc8201de160)
    /usr/lib/go/src/net/http/transport.go:1009 +0x40c
created by net/http.(*Transport).dialConn
    /usr/lib/go/src/net/http/transport.go:686 +0xc9d
FAIL    github.com/prometheus/prometheus/notification   0.287s
ok      github.com/prometheus/prometheus/promql 3.452s
ok      github.com/prometheus/prometheus/retrieval  1.634s
ok      github.com/prometheus/prometheus/retrieval/discovery    0.137s
?       github.com/prometheus/prometheus/retrieval/discovery/kubernetes [no test files]
?       github.com/prometheus/prometheus/retrieval/discovery/marathon   [no test files]
ok      github.com/prometheus/prometheus/rules  0.299s
?       github.com/prometheus/prometheus/storage    [no test files]
ok      github.com/prometheus/prometheus/storage/local  35.359s
ok      github.com/prometheus/prometheus/storage/local/codable  0.015s
?       github.com/prometheus/prometheus/storage/local/index    [no test files]
ok      github.com/prometheus/prometheus/storage/metric 0.013s
ok      github.com/prometheus/prometheus/storage/remote 0.056s
ok      github.com/prometheus/prometheus/storage/remote/graphite    0.021s
ok      github.com/prometheus/prometheus/storage/remote/influxdb    0.029s
ok      github.com/prometheus/prometheus/storage/remote/opentsdb    0.035s
ok      github.com/prometheus/prometheus/template   0.134s
?       github.com/prometheus/prometheus/util/cli   [no test files]
ok      github.com/prometheus/prometheus/util/flock 0.022s
?       github.com/prometheus/prometheus/util/httputil  [no test files]
?       github.com/prometheus/prometheus/util/stats [no test files]
ok      github.com/prometheus/prometheus/util/strutil   0.019s
?       github.com/prometheus/prometheus/util/testutil  [no test files]
?       github.com/prometheus/prometheus/util/treecache [no test files]
?       github.com/prometheus/prometheus/version    [no test files]
ok      github.com/prometheus/prometheus/web    0.034s
ok      github.com/prometheus/prometheus/web/api/legacy 0.234s
ok      github.com/prometheus/prometheus/web/api/v1 0.101s
?       github.com/prometheus/prometheus/web/ui [no test files]
Makefile:29: recipe for target 'test' failed
make: *** [test] Error 1
% echo $?
2
%

RichiH · Jan 22, 2016

Built and tested node_exporter, blackbox_exporter, and Grafana; I guess it's really Prometheus.

grobie · Jan 22, 2016

This looks like a race condition, hopefully only in the test code. Do you get this every time?

RichiH · Jan 22, 2016

I get it every time, but with different output. That would support the race condition. Note that his hardware is faster than the Raspi someone uses, but slower than pretty much anything people would ever use for Prometheus elsewhere.

Need more pastes?

RichiH · Jan 22, 2016

Data point: Full CPU load or no other load, the test errors out.

RichiH · Jan 22, 2016

>> formatting code
>> building binaries
 >   prometheus
 >   promtool
>> running tests
?       github.com/prometheus/prometheus/cmd/prometheus [no test files]
?       github.com/prometheus/prometheus/cmd/promtool   [no test files]
ok      github.com/prometheus/prometheus/config 0.187s
ok      github.com/prometheus/prometheus/notification   0.238s
ok      github.com/prometheus/prometheus/promql 3.473s
ok      github.com/prometheus/prometheus/retrieval  1.542s
ok      github.com/prometheus/prometheus/retrieval/discovery    0.149s
?       github.com/prometheus/prometheus/retrieval/discovery/kubernetes [no test files]
?       github.com/prometheus/prometheus/retrieval/discovery/marathon   [no test files]
ok      github.com/prometheus/prometheus/rules  0.297s
?       github.com/prometheus/prometheus/storage    [no test files]
time="2016-01-22T22:39:16+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T22:39:16+01:00" level=info msg="Done checkpointing fingerprint mappings in 6.142109ms." source="persistence.go:1479" 
time="2016-01-22T22:39:16+01:00" level=info msg="Collision detected for fingerprint 0000000000100001, metric {bar=\"foo\"}, mapping to new fingerprint 0000000000000001." source="mapper.go:166" 
time="2016-01-22T22:39:16+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T22:39:16+01:00" level=info msg="Done checkpointing fingerprint mappings in 3.044598ms." source="persistence.go:1479" 
time="2016-01-22T22:39:16+01:00" level=info msg="Collision detected for fingerprint 0000000000100001, metric {foo=\"bar\"}, mapping to new fingerprint 0000000000000002." source="mapper.go:151" 
time="2016-01-22T22:39:16+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T22:39:16+01:00" level=info msg="Done checkpointing fingerprint mappings in 5.761021ms." source="persistence.go:1479" 
time="2016-01-22T22:39:16+01:00" level=info msg="Collision detected for fingerprint 0000000000100002, metric {bar=\"bumms\", dings=\"foo\"}, mapping to new fingerprint 0000000000000003." source="mapper.go:166" 
time="2016-01-22T22:39:16+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T22:39:16+01:00" level=info msg="Done checkpointing fingerprint mappings in 2.832227ms." source="persistence.go:1479" 
time="2016-01-22T22:39:16+01:00" level=info msg="Collision detected for fingerprint 0000000000000001, metric {bumms=\"dings\"}, mapping to new fingerprint 0000000000000004." source="mapper.go:166" 
time="2016-01-22T22:39:16+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T22:39:16+01:00" level=info msg="Done checkpointing fingerprint mappings in 2.610185ms." source="persistence.go:1479" 
time="2016-01-22T22:39:16+01:00" level=info msg="Collision detected for fingerprint 0000000000000001, metric {bar=\"foo\", bumms=\"dings\"}, mapping to new fingerprint 0000000000000005." source="mapper.go:151" 
time="2016-01-22T22:39:16+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T22:39:16+01:00" level=info msg="Done checkpointing fingerprint mappings in 3.1469ms." source="persistence.go:1479" 
time="2016-01-22T22:39:16+01:00" level=info msg="Collision detected for fingerprint 0000000000100002, metric {dings=\"bar\", foo=\"bumms\"}, mapping to new fingerprint 0000000000000006." source="mapper.go:151" 
time="2016-01-22T22:39:17+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:17+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 8.254275ms." source="persistence.go:570" 
time="2016-01-22T22:39:17+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:17+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 11.363335ms." source="persistence.go:570" 
time="2016-01-22T22:39:17+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T22:39:17+01:00" level=info msg="Done checkpointing fingerprint mappings in 12.110329ms." source="persistence.go:1479" 
time="2016-01-22T22:39:18+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:39:18+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:39:18+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:39:18+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:39:18+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:39:18+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:39:18+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:39:18+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:18+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 10.73593ms." source="persistence.go:570" 
time="2016-01-22T22:39:18+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:39:18+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:39:18+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:39:18+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:39:18+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:39:18+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:39:18+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:39:18+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:39:18+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:18+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 18.695695ms." source="persistence.go:570" 
time="2016-01-22T22:39:18+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:39:19+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:39:19+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:39:19+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:39:19+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:39:19+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:39:19+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:39:19+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:39:19+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:19+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 2.968592ms." source="persistence.go:570" 
time="2016-01-22T22:39:19+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:39:19+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:39:19+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:39:26+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:39:26+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:39:26+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:39:26+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:39:26+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:39:26+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:26+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 5.802921ms." source="persistence.go:570" 
time="2016-01-22T22:39:26+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:39:28+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:39:28+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:39:39+01:00" level=info msg="test done, closing" source="storage_test.go:628" 
time="2016-01-22T22:39:39+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:39:39+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:39:39+01:00" level=info msg="Completed maintenance sweep through 1 in-memory fingerprints in 795.12564ms." source="storage.go:816" 
time="2016-01-22T22:39:39+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:39+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 136.224007ms." source="persistence.go:570" 
time="2016-01-22T22:39:39+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:39:39+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:39:39+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:39:39+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:39+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 74.152298ms." source="persistence.go:570" 
time="2016-01-22T22:39:39+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:39:40+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:39:40+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:39:50+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:50+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 188.867126ms." source="persistence.go:570" 
time="2016-01-22T22:39:57+01:00" level=info msg="test done, closing" source="storage_test.go:628" 
time="2016-01-22T22:39:57+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:39:57+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:39:57+01:00" level=info msg="Completed maintenance sweep through 1 in-memory fingerprints in 7.155131561s." source="storage.go:816" 
time="2016-01-22T22:39:57+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:39:57+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:39:57+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:39:57+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:57+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 92.786253ms." source="persistence.go:570" 
time="2016-01-22T22:39:57+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:39:57+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:39:57+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:39:58+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:39:58+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:39:58+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:39:58+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:39:58+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:39:58+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:58+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 5.84177ms." source="persistence.go:570" 
time="2016-01-22T22:39:58+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:39:58+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:39:58+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:39:58+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:39:58+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:39:58+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:39:58+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:39:58+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:39:58+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:58+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 10.670532ms." source="persistence.go:570" 
time="2016-01-22T22:39:58+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:39:59+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:39:59+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:39:59+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:39:59+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:39:59+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:39:59+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:39:59+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:39:59+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:39:59+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 6.176365ms." source="persistence.go:570" 
time="2016-01-22T22:39:59+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:40:00+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:40:00+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:40:01+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:40:01+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:40:01+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:40:01+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:40:01+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:40:01+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:40:01+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 6.056014ms." source="persistence.go:570" 
time="2016-01-22T22:40:01+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:40:01+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:40:01+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:40:02+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:40:02+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:40:02+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:40:02+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:40:02+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:40:02+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:40:02+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 18.76879ms." source="persistence.go:570" 
time="2016-01-22T22:40:02+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:40:02+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:40:02+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:40:03+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:40:03+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:40:03+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:40:03+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:40:03+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:40:03+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:40:03+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 7.898361ms." source="persistence.go:570" 
time="2016-01-22T22:40:03+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:40:04+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:40:04+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:40:04+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:40:04+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:40:04+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:40:04+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:40:04+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:40:04+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:40:04+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 6.901328ms." source="persistence.go:570" 
time="2016-01-22T22:40:04+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
--- FAIL: TestEvictAndLoadChunkDescsType0 (0.77s)
    storage_test.go:1209: Expected number of chunkDescs to decrease, old number 79, current number 79.
time="2016-01-22T22:40:04+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:40:04+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:40:05+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:40:05+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:40:05+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:40:05+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:40:05+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:40:05+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:40:05+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 4.141059ms." source="persistence.go:570" 
time="2016-01-22T22:40:05+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T22:40:05+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T22:40:05+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T22:40:05+01:00" level=warning msg="Ignoring sample with out-of-order timestamp for fingerprint d8889b7402187e08 (out_of_order): 0.001 is not after 0.002" source="storage.go:577" 
time="2016-01-22T22:40:05+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T22:40:05+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T22:40:05+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T22:40:05+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T22:40:05+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T22:40:05+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T22:40:05+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 4.26429ms." source="persistence.go:570" 
time="2016-01-22T22:40:05+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
FAIL
FAIL    github.com/prometheus/prometheus/storage/local  49.002s
ok      github.com/prometheus/prometheus/storage/local/codable  0.040s
?       github.com/prometheus/prometheus/storage/local/index    [no test files]
ok      github.com/prometheus/prometheus/storage/metric 0.037s
ok      github.com/prometheus/prometheus/storage/remote 0.078s
ok      github.com/prometheus/prometheus/storage/remote/graphite    0.027s
ok      github.com/prometheus/prometheus/storage/remote/influxdb    0.036s
ok      github.com/prometheus/prometheus/storage/remote/opentsdb    0.055s
ok      github.com/prometheus/prometheus/template   0.204s
?       github.com/prometheus/prometheus/util/cli   [no test files]
ok      github.com/prometheus/prometheus/util/flock 0.025s
?       github.com/prometheus/prometheus/util/httputil  [no test files]
?       github.com/prometheus/prometheus/util/stats [no test files]
ok      github.com/prometheus/prometheus/util/strutil   0.034s
?       github.com/prometheus/prometheus/util/testutil  [no test files]
?       github.com/prometheus/prometheus/util/treecache [no test files]
?       github.com/prometheus/prometheus/version    [no test files]
ok      github.com/prometheus/prometheus/web    0.042s
ok      github.com/prometheus/prometheus/web/api/legacy 0.244s
ok      github.com/prometheus/prometheus/web/api/v1 0.144s
?       github.com/prometheus/prometheus/web/ui [no test files]
Makefile:29: recipe for target 'test' failed
make: *** [test] Error 1

RichiH · Jan 22, 2016

>> formatting code
>> building binaries
 >   prometheus
 >   promtool
>> running tests
?       github.com/prometheus/prometheus/cmd/prometheus [no test files]
?       github.com/prometheus/prometheus/cmd/promtool   [no test files]
ok      github.com/prometheus/prometheus/config 0.136s
time="2016-01-22T21:57:47+01:00" level=warning msg="Alert batch larger than queue capacity, dropping 64 alerts" source="notification.go:213" 
time="2016-01-22T21:57:47+01:00" level=warning msg="Alert notification queue full, dropping 64 alerts" source="notification.go:222" 
time="2016-01-22T21:57:47+01:00" level=info msg="Stopping notification handler..." source="notification.go:275" 
panic: send on closed channel

goroutine 6 [running]:
github.com/prometheus/prometheus/notification.(*Handler).setMore(0xc820224000)
    /home/richih/work/go/src/github.com/prometheus/prometheus/notification/notification.go:236 +0x3d
github.com/prometheus/prometheus/notification.(*Handler).Run(0xc820224000)
    /home/richih/work/go/src/github.com/prometheus/prometheus/notification/notification.go:197 +0x53f
created by github.com/prometheus/prometheus/notification.TestHandlerFull
    /home/richih/work/go/src/github.com/prometheus/prometheus/notification/notification_test.go:183 +0x505

goroutine 1 [runnable]:
testing.(*T).report(0xc82020a090)
    /usr/lib/go/src/testing/testing.go:508
testing.RunTests(0x936ce0, 0xa977e0, 0x3, 0x3, 0x4ea301)
    /usr/lib/go/src/testing/testing.go:570 +0x929
testing.(*M).Run(0xc8200ebee8, 0x4ea423)
    /usr/lib/go/src/testing/testing.go:494 +0x70
main.main()
    github.com/prometheus/prometheus/notification/_test/_testmain.go:58 +0x116

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
    /usr/lib/go/src/runtime/asm_amd64.s:1721 +0x1

goroutine 5 [IO wait]:
net.runtime_pollWait(0x7f16bd18ef68, 0x72, 0xc820072080)
    /usr/lib/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc820058290, 0x72, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc820058290, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).accept(0xc820058230, 0x0, 0x7f16bf7b5028, 0xc820206340)
    /usr/lib/go/src/net/fd_unix.go:408 +0x27c
net.(*TCPListener).AcceptTCP(0xc82002c418, 0xc82017a240, 0x0, 0x0)
    /usr/lib/go/src/net/tcpsock_posix.go:254 +0x4d
net.(*TCPListener).Accept(0xc82002c418, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/tcpsock_posix.go:264 +0x3d
net/http/httptest.(*historyListener).Accept(0xc820010ea0, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/http/httptest/server.go:48 +0x63
net/http.(*Server).Serve(0xc8200141e0, 0x7f16bd18f028, 0xc820010ea0, 0x0, 0x0)
    /usr/lib/go/src/net/http/server.go:1887 +0xb3
created by net/http/httptest.(*Server).Start
    /usr/lib/go/src/net/http/httptest/server.go:109 +0x380

goroutine 35 [runnable]:
syscall.Syscall(0x0, 0x5, 0xc8201eb000, 0x1000, 0xffffffffffffffff, 0x0, 0xb)
    /usr/lib/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.read(0x5, 0xc8201eb000, 0x1000, 0x1000, 0x72, 0x0, 0x0)
    /usr/lib/go/src/syscall/zsyscall_linux_amd64.go:783 +0x5f
syscall.Read(0x5, 0xc8201eb000, 0x1000, 0x1000, 0xc82001d50c, 0x0, 0x0)
    /usr/lib/go/src/syscall/syscall_unix.go:160 +0x4d
net.(*netFD).Read(0xc82016a0e0, 0xc8201eb000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/fd_unix.go:228 +0x18b
net.(*conn).Read(0xc82016e408, 0xc8201eb000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/net.go:172 +0xe4
net/http.(*liveSwitchReader).Read(0xc8201721a8, 0xc8201eb000, 0x1000, 0x1000, 0xc8202f0000, 0x0, 0x0)
    /usr/lib/go/src/net/http/server.go:219 +0xa4
io.(*LimitedReader).Read(0xc820206320, 0xc8201eb000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/io/io.go:427 +0xbd
bufio.(*Reader).fill(0xc820176060)
    /usr/lib/go/src/bufio/bufio.go:97 +0x1e9
bufio.(*Reader).Peek(0xc820176060, 0x4, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/bufio/bufio.go:132 +0xcc
net/http.(*conn).readRequest(0xc820172160, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/http/server.go:629 +0x2bb
net/http.(*conn).serve(0xc820172160)
    /usr/lib/go/src/net/http/server.go:1319 +0x727
created by net/http.(*Server).Serve
    /usr/lib/go/src/net/http/server.go:1910 +0x3f6

goroutine 9 [IO wait]:
net.runtime_pollWait(0x7f16bd18ede8, 0x72, 0xc820072080)
    /usr/lib/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc820058a00, 0x72, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc820058a00, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).Read(0xc8200589a0, 0xc820247000, 0x1000, 0x1000, 0x0, 0x7f16bd189028, 0xc820072080)
    /usr/lib/go/src/net/fd_unix.go:232 +0x23a
net.(*conn).Read(0xc82002c440, 0xc820247000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/net.go:172 +0xe4
net/http.noteEOFReader.Read(0x7f16bd149028, 0xc82002c440, 0xc8201a61b8, 0xc820247000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/http/transport.go:1370 +0x67
net/http.(*noteEOFReader).Read(0xc8202deb00, 0xc820247000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    <autogenerated>:126 +0xd0
bufio.(*Reader).fill(0xc8202dd0e0)
    /usr/lib/go/src/bufio/bufio.go:97 +0x1e9
bufio.(*Reader).Peek(0xc8202dd0e0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/bufio/bufio.go:132 +0xcc
net/http.(*persistConn).readLoop(0xc8201a6160)
    /usr/lib/go/src/net/http/transport.go:876 +0xf7
created by net/http.(*Transport).dialConn
    /usr/lib/go/src/net/http/transport.go:685 +0xc78

goroutine 10 [select]:
net/http.(*persistConn).writeLoop(0xc8201a6160)
    /usr/lib/go/src/net/http/transport.go:1009 +0x40c
created by net/http.(*Transport).dialConn
    /usr/lib/go/src/net/http/transport.go:686 +0xc9d
FAIL    github.com/prometheus/prometheus/notification   0.221s
ok      github.com/prometheus/prometheus/promql 3.995s
ok      github.com/prometheus/prometheus/retrieval  1.772s
ok      github.com/prometheus/prometheus/retrieval/discovery    0.118s
?       github.com/prometheus/prometheus/retrieval/discovery/kubernetes [no test files]
?       github.com/prometheus/prometheus/retrieval/discovery/marathon   [no test files]
ok      github.com/prometheus/prometheus/rules  0.289s
?       github.com/prometheus/prometheus/storage    [no test files]
time="2016-01-22T21:59:08+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T21:59:08+01:00" level=info msg="Done checkpointing fingerprint mappings in 4.369235ms." source="persistence.go:1479" 
time="2016-01-22T21:59:08+01:00" level=info msg="Collision detected for fingerprint 0000000000100001, metric {bar=\"foo\"}, mapping to new fingerprint 0000000000000001." source="mapper.go:166" 
time="2016-01-22T21:59:08+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T21:59:08+01:00" level=info msg="Done checkpointing fingerprint mappings in 4.157974ms." source="persistence.go:1479" 
time="2016-01-22T21:59:08+01:00" level=info msg="Collision detected for fingerprint 0000000000100001, metric {foo=\"bar\"}, mapping to new fingerprint 0000000000000002." source="mapper.go:151" 
time="2016-01-22T21:59:08+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T21:59:08+01:00" level=info msg="Done checkpointing fingerprint mappings in 3.165992ms." source="persistence.go:1479" 
time="2016-01-22T21:59:08+01:00" level=info msg="Collision detected for fingerprint 0000000000100002, metric {bar=\"bumms\", dings=\"foo\"}, mapping to new fingerprint 0000000000000003." source="mapper.go:166" 
time="2016-01-22T21:59:08+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T21:59:08+01:00" level=info msg="Done checkpointing fingerprint mappings in 5.061846ms." source="persistence.go:1479" 
time="2016-01-22T21:59:08+01:00" level=info msg="Collision detected for fingerprint 0000000000000001, metric {bumms=\"dings\"}, mapping to new fingerprint 0000000000000004." source="mapper.go:166" 
time="2016-01-22T21:59:08+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T21:59:08+01:00" level=info msg="Done checkpointing fingerprint mappings in 3.113879ms." source="persistence.go:1479" 
time="2016-01-22T21:59:08+01:00" level=info msg="Collision detected for fingerprint 0000000000000001, metric {bar=\"foo\", bumms=\"dings\"}, mapping to new fingerprint 0000000000000005." source="mapper.go:151" 
time="2016-01-22T21:59:08+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T21:59:08+01:00" level=info msg="Done checkpointing fingerprint mappings in 3.593577ms." source="persistence.go:1479" 
time="2016-01-22T21:59:08+01:00" level=info msg="Collision detected for fingerprint 0000000000100002, metric {dings=\"bar\", foo=\"bumms\"}, mapping to new fingerprint 0000000000000006." source="mapper.go:151" 
time="2016-01-22T21:59:08+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:08+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 8.101817ms." source="persistence.go:570" 
time="2016-01-22T21:59:09+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:09+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 6.407881ms." source="persistence.go:570" 
time="2016-01-22T21:59:09+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456" 
time="2016-01-22T21:59:09+01:00" level=info msg="Done checkpointing fingerprint mappings in 2.857625ms." source="persistence.go:1479" 
time="2016-01-22T21:59:09+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:09+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:09+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:09+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:09+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:09+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:09+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:09+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:09+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 30.871209ms." source="persistence.go:570" 
time="2016-01-22T21:59:09+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:10+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:10+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:10+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:10+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:10+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:10+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:10+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:10+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:10+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 15.478002ms." source="persistence.go:570" 
time="2016-01-22T21:59:10+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:10+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:10+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:10+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:10+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:10+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:10+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:10+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:10+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:10+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 6.861655ms." source="persistence.go:570" 
time="2016-01-22T21:59:10+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:10+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:10+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:18+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:18+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:18+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:18+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:18+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:18+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:18+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 4.605548ms." source="persistence.go:570" 
time="2016-01-22T21:59:18+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:20+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:20+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:31+01:00" level=info msg="test done, closing" source="storage_test.go:628" 
time="2016-01-22T21:59:31+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:31+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:31+01:00" level=info msg="Completed maintenance sweep through 1 in-memory fingerprints in 933.035819ms." source="storage.go:816" 
time="2016-01-22T21:59:31+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:31+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:31+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:31+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:31+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 72.426091ms." source="persistence.go:570" 
time="2016-01-22T21:59:31+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:32+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:32+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:42+01:00" level=info msg="test done, closing" source="storage_test.go:628" 
time="2016-01-22T21:59:42+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:42+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:42+01:00" level=info msg="Completed maintenance sweep through 1 in-memory fingerprints in 928.196585ms." source="storage.go:816" 
time="2016-01-22T21:59:43+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:43+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:43+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:43+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:43+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 81.427448ms." source="persistence.go:570" 
time="2016-01-22T21:59:43+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:43+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:43+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:43+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:43+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:43+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:43+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:43+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:43+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:43+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 11.076262ms." source="persistence.go:570" 
time="2016-01-22T21:59:43+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:43+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:43+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:43+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:43+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:43+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:43+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:43+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:43+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:43+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 9.253321ms." source="persistence.go:570" 
time="2016-01-22T21:59:43+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:44+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:44+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:45+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:45+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:45+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:45+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:45+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:45+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:45+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 5.335608ms." source="persistence.go:570" 
time="2016-01-22T21:59:45+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:45+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:45+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:45+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:45+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:45+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:45+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:45+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:45+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:45+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 7.795331ms." source="persistence.go:570" 
time="2016-01-22T21:59:45+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:45+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:45+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:46+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:46+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:46+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:46+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:46+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:46+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:46+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 4.352066ms." source="persistence.go:570" 
time="2016-01-22T21:59:46+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:46+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:46+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:47+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:47+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:47+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:47+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:47+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:47+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:47+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 4.136301ms." source="persistence.go:570" 
time="2016-01-22T21:59:47+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:47+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:47+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:47+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:47+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:47+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:47+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:47+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:47+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:47+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 6.491132ms." source="persistence.go:570" 
time="2016-01-22T21:59:47+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
--- FAIL: TestEvictAndLoadChunkDescsType0 (0.48s)
    storage_test.go:1209: Expected number of chunkDescs to decrease, old number 79, current number 79.
time="2016-01-22T21:59:47+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:47+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:47+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:47+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:47+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:47+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:47+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:47+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:47+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 3.79567ms." source="persistence.go:570" 
time="2016-01-22T21:59:48+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-22T21:59:48+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268" 
time="2016-01-22T21:59:48+01:00" level=info msg="0 series loaded." source="storage.go:273" 
time="2016-01-22T21:59:48+01:00" level=warning msg="Ignoring sample with out-of-order timestamp for fingerprint d8889b7402187e08 (out_of_order): 0.001 is not after 0.002" source="storage.go:577" 
time="2016-01-22T21:59:48+01:00" level=info msg="Stopping local storage..." source="storage.go:289" 
time="2016-01-22T21:59:48+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291" 
time="2016-01-22T21:59:48+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873" 
time="2016-01-22T21:59:48+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295" 
time="2016-01-22T21:59:48+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693" 
time="2016-01-22T21:59:48+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546" 
time="2016-01-22T21:59:48+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 8.492065ms." source="persistence.go:570" 
time="2016-01-22T21:59:48+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
FAIL
FAIL    github.com/prometheus/prometheus/storage/local  40.424s
ok      github.com/prometheus/prometheus/storage/local/codable  0.019s
?       github.com/prometheus/prometheus/storage/local/index    [no test files]
ok      github.com/prometheus/prometheus/storage/metric 0.037s
ok      github.com/prometheus/prometheus/storage/remote 0.079s
ok      github.com/prometheus/prometheus/storage/remote/graphite    0.045s
ok      github.com/prometheus/prometheus/storage/remote/influxdb    0.064s
ok      github.com/prometheus/prometheus/storage/remote/opentsdb    0.043s
ok      github.com/prometheus/prometheus/template   0.158s
?       github.com/prometheus/prometheus/util/cli   [no test files]
ok      github.com/prometheus/prometheus/util/flock 0.028s
?       github.com/prometheus/prometheus/util/httputil  [no test files]
?       github.com/prometheus/prometheus/util/stats [no test files]
ok      github.com/prometheus/prometheus/util/strutil   0.034s
?       github.com/prometheus/prometheus/util/testutil  [no test files]
?       github.com/prometheus/prometheus/util/treecache [no test files]
?       github.com/prometheus/prometheus/version    [no test files]
ok      github.com/prometheus/prometheus/web    0.035s
ok      github.com/prometheus/prometheus/web/api/legacy 0.239s
ok      github.com/prometheus/prometheus/web/api/v1 0.106s
?       github.com/prometheus/prometheus/web/ui [no test files]
Makefile:29: recipe for target 'test' failed
make: *** [test] Error 1

fabxc · Jan 25, 2016

I'm looking into the notification panic.

@beorn7 The second test output is storage related. I guess both cases are timing issues in the tests and thus not critical but if maybe they are easy to fix.

fabxc · Jan 25, 2016

@RichiH As far as the notification test goes my first suspect would be that the timeout is too short for a slow machine, which causes a race with the defer h.Stop().

I pushed the notifytestfix branch – would you mind testing whether the panic still happens with that one?

RichiH · Jan 25, 2016

Happened one time out of three

>> formatting code
>> building binaries
 >   prometheus
 >   promtool
>> running tests
?       github.com/prometheus/prometheus/cmd/prometheus [no test files]
?       github.com/prometheus/prometheus/cmd/promtool   [no test files]
ok      github.com/prometheus/prometheus/config 0.068s
ok      github.com/prometheus/prometheus/notification   0.329s
ok      github.com/prometheus/prometheus/promql 3.203s
ok      github.com/prometheus/prometheus/retrieval      1.586s
ok      github.com/prometheus/prometheus/retrieval/discovery    0.101s
?       github.com/prometheus/prometheus/retrieval/discovery/kubernetes [no test files]
?       github.com/prometheus/prometheus/retrieval/discovery/marathon   [no test files]
ok      github.com/prometheus/prometheus/rules  0.206s
?       github.com/prometheus/prometheus/storage        [no test files]
time="2016-01-25T20:57:03+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456"
time="2016-01-25T20:57:03+01:00" level=info msg="Done checkpointing fingerprint mappings in 3.051441ms." source="persistence.go:1479"
time="2016-01-25T20:57:03+01:00" level=info msg="Collision detected for fingerprint 0000000000100001, metric {bar=\"foo\"}, mapping to new fingerprint 0000000000000001." source="mapper.go:166"
time="2016-01-25T20:57:03+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456"
time="2016-01-25T20:57:03+01:00" level=info msg="Done checkpointing fingerprint mappings in 3.569925ms." source="persistence.go:1479"
time="2016-01-25T20:57:03+01:00" level=info msg="Collision detected for fingerprint 0000000000100001, metric {foo=\"bar\"}, mapping to new fingerprint 0000000000000002." source="mapper.go:151"
time="2016-01-25T20:57:03+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456"
time="2016-01-25T20:57:03+01:00" level=info msg="Done checkpointing fingerprint mappings in 2.672819ms." source="persistence.go:1479"
time="2016-01-25T20:57:03+01:00" level=info msg="Collision detected for fingerprint 0000000000100002, metric {bar=\"bumms\", dings=\"foo\"}, mapping to new fingerprint 0000000000000003." source="mapper.go:166"
time="2016-01-25T20:57:03+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456"
time="2016-01-25T20:57:03+01:00" level=info msg="Done checkpointing fingerprint mappings in 2.524617ms." source="persistence.go:1479"
time="2016-01-25T20:57:03+01:00" level=info msg="Collision detected for fingerprint 0000000000000001, metric {bumms=\"dings\"}, mapping to new fingerprint 0000000000000004." source="mapper.go:166"
time="2016-01-25T20:57:03+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456"
time="2016-01-25T20:57:03+01:00" level=info msg="Done checkpointing fingerprint mappings in 2.355941ms." source="persistence.go:1479"
time="2016-01-25T20:57:03+01:00" level=info msg="Collision detected for fingerprint 0000000000000001, metric {bar=\"foo\", bumms=\"dings\"}, mapping to new fingerprint 0000000000000005." source="mapper.go:151"
time="2016-01-25T20:57:03+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456"
time="2016-01-25T20:57:03+01:00" level=info msg="Done checkpointing fingerprint mappings in 2.533971ms." source="persistence.go:1479"
time="2016-01-25T20:57:03+01:00" level=info msg="Collision detected for fingerprint 0000000000100002, metric {dings=\"bar\", foo=\"bumms\"}, mapping to new fingerprint 0000000000000006." source="mapper.go:151"
time="2016-01-25T20:57:03+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:03+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 7.182873ms." source="persistence.go:570"
time="2016-01-25T20:57:03+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:03+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 5.271283ms." source="persistence.go:570"
time="2016-01-25T20:57:03+01:00" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1456"
time="2016-01-25T20:57:03+01:00" level=info msg="Done checkpointing fingerprint mappings in 7.244033ms." source="persistence.go:1479"
time="2016-01-25T20:57:04+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:04+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:04+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:04+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:04+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:04+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:04+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:04+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:04+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 11.191326ms." source="persistence.go:570"
time="2016-01-25T20:57:04+01:00" level=info msg="Local storage stopped." source="storage.go:307"
time="2016-01-25T20:57:04+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:04+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:04+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:04+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:04+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:04+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:04+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:04+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:04+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 27.489401ms." source="persistence.go:570"
time="2016-01-25T20:57:04+01:00" level=info msg="Local storage stopped." source="storage.go:307"
time="2016-01-25T20:57:05+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:05+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:05+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:05+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:05+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:05+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:05+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:05+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:05+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 3.076629ms." source="persistence.go:570"
time="2016-01-25T20:57:05+01:00" level=info msg="Local storage stopped." source="storage.go:307"
time="2016-01-25T20:57:05+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:05+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:11+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:11+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:11+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:11+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:11+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:11+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:11+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 4.876154ms." source="persistence.go:570"
time="2016-01-25T20:57:11+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-25T20:57:12+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:12+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:23+01:00" level=info msg="test done, closing" source="storage_test.go:631"
time="2016-01-25T20:57:23+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:23+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:23+01:00" level=info msg="Completed maintenance sweep through 1 in-memory fingerprints in 273.785937ms." source="storage.go:816"
time="2016-01-25T20:57:23+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:23+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:23+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:23+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:23+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 61.74475ms." source="persistence.go:570"
time="2016-01-25T20:57:23+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-25T20:57:23+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:23+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:33+01:00" level=info msg="test done, closing" source="storage_test.go:631"
time="2016-01-25T20:57:33+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:33+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:33+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:33+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:33+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:33+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:33+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 29.384524ms." source="persistence.go:570"
time="2016-01-25T20:57:33+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-25T20:57:33+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:33+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:33+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:33+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:33+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:33+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:34+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:34+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:34+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 13.682809ms." source="persistence.go:570"
time="2016-01-25T20:57:34+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-25T20:57:34+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:34+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:34+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:34+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:34+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:34+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:34+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:34+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:34+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 3.729827ms." source="persistence.go:570"
time="2016-01-25T20:57:34+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-25T20:57:34+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:34+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:35+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:35+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:35+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:35+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:35+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:35+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:35+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 5.446325ms." source="persistence.go:570"
time="2016-01-25T20:57:35+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-25T20:57:35+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:35+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:35+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:35+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:35+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:35+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:35+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:35+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:35+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 3.753977ms." source="persistence.go:570"
time="2016-01-25T20:57:35+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-25T20:57:35+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:35+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:35+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:35+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:35+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:35+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:35+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:35+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:35+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 2.593337ms." source="persistence.go:570"
time="2016-01-25T20:57:35+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-25T20:57:36+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:36+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:36+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:36+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:36+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:36+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:36+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:36+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:36+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 2.742099ms." source="persistence.go:570"
time="2016-01-25T20:57:36+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-25T20:57:36+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:36+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:36+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:36+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:36+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:36+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:36+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:36+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:36+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 2.955309ms." source="persistence.go:570"
time="2016-01-25T20:57:36+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
time="2016-01-25T20:57:36+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:36+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:36+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:36+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:36+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:36+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:36+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:36+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:36+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 3.651609ms." source="persistence.go:570"
time="2016-01-25T20:57:36+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
--- FAIL: TestEvictAndLoadChunkDescsType1 (0.22s)
        storage_test.go:1212: Expected number of chunkDescs to decrease, old number 56, current number 56.
time="2016-01-25T20:57:37+01:00" level=info msg="Loading series map and head chunks..." source="storage.go:268"
time="2016-01-25T20:57:37+01:00" level=info msg="0 series loaded." source="storage.go:273"
time="2016-01-25T20:57:37+01:00" level=warning msg="Ignoring sample with out-of-order timestamp for fingerprint d8889b7402187e08 (out_of_order): 0.001 is not after 0.002" source="storage.go:577"
time="2016-01-25T20:57:37+01:00" level=info msg="Stopping local storage..." source="storage.go:289"
time="2016-01-25T20:57:37+01:00" level=info msg="Stopping maintenance loop..." source="storage.go:291"
time="2016-01-25T20:57:37+01:00" level=info msg="Maintenance loop stopped." source="storage.go:873"
time="2016-01-25T20:57:37+01:00" level=info msg="Stopping chunk eviction..." source="storage.go:295"
time="2016-01-25T20:57:37+01:00" level=info msg="Chunk eviction stopped." source="storage.go:693"
time="2016-01-25T20:57:37+01:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:546"
time="2016-01-25T20:57:37+01:00" level=info msg="Done checkpointing in-memory metrics and chunks in 2.55689ms." source="persistence.go:570"
time="2016-01-25T20:57:37+01:00" level=info msg="Local storage stopped." source="storage.go:307" 
FAIL
FAIL    github.com/prometheus/prometheus/storage/local  33.950s
ok      github.com/prometheus/prometheus/storage/local/codable  0.014s
?       github.com/prometheus/prometheus/storage/local/index    [no test files]
ok      github.com/prometheus/prometheus/storage/metric 0.021s
ok      github.com/prometheus/prometheus/storage/remote 0.050s
ok      github.com/prometheus/prometheus/storage/remote/graphite        0.021s
ok      github.com/prometheus/prometheus/storage/remote/influxdb        0.030s
ok      github.com/prometheus/prometheus/storage/remote/opentsdb        0.048s
ok      github.com/prometheus/prometheus/template       0.153s
?       github.com/prometheus/prometheus/util/cli       [no test files]
ok      github.com/prometheus/prometheus/util/flock     0.018s
?       github.com/prometheus/prometheus/util/httputil  [no test files]
?       github.com/prometheus/prometheus/util/stats     [no test files]
ok      github.com/prometheus/prometheus/util/strutil   0.063s
?       github.com/prometheus/prometheus/util/testutil  [no test files]
?       github.com/prometheus/prometheus/util/treecache [no test files]
?       github.com/prometheus/prometheus/version        [no test files]
ok      github.com/prometheus/prometheus/web    0.035s
ok      github.com/prometheus/prometheus/web/api/legacy 0.158s
ok      github.com/prometheus/prometheus/web/api/v1     0.096s
?       github.com/prometheus/prometheus/web/ui [no test files]
Makefile:29: recipe for target 'test' failed
make: *** [test] Error 1

Return code 2

fabxc · Jan 25, 2016

That's the storage test failure. Did the panic of the notification test happen again as well?

RichiH · Jan 26, 2016

Nope,that's gone. Richard Sent by mobile; excuse my brevity.

fabxc · Jan 26, 2016

#1348 fixes the issue of the original title. You'll know best how to fix the storage test, @beorn7. Might just need a larger time buffer as well.

brian-brazil · Apr 8, 2016

Can we close this off? I see no relevant breakages (just that 386 compiler issue) on my build server in the past month.

beorn7 · Apr 8, 2016

How about we still merge #1454 ? It's only increasing one of the nasty sleep times. Would be much better to get rid of those altogether, but that will be quite an effort.

beorn7 · Apr 8, 2016

@fabxc just merged it. So I'm closing this. Please re-open if new evidence shows up.

lock · Mar 24, 2019

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.

grobie changed the title ~~Error during build~~ Panic in notification test Jan 22, 2016

fabxc referenced this issue Jan 26, 2016
Merged
Increase notification test timeouts #1348

fabxc changed the title ~~Panic in notification test~~ Timing issues in storage test Jan 26, 2016

fabxc assigned beorn7 Jan 26, 2016

beorn7 added the bug label Jan 26, 2016

beorn7 referenced this issue Mar 3, 2016
Merged
Give TestEvictAndLoadChunkDescs more time to actually evict #1454

beorn7 closed this Apr 8, 2016

lock bot locked and limited conversation to collaborators Mar 24, 2019

prometheus/prometheus

Join GitHub today

Timing issues in storage test #1337

Comments

RichiH commented Jan 22, 2016

This comment has been minimized.

RichiH commented Jan 22, 2016

This comment has been minimized.

grobie commented Jan 22, 2016

grobie changed the title Error during build Panic in notification test Jan 22, 2016

This comment has been minimized.

RichiH commented Jan 22, 2016

This comment has been minimized.

RichiH commented Jan 22, 2016

This comment has been minimized.

RichiH commented Jan 22, 2016

This comment has been minimized.

RichiH commented Jan 22, 2016

This comment has been minimized.

fabxc commented Jan 25, 2016

This comment has been minimized.

fabxc commented Jan 25, 2016

This comment has been minimized.

RichiH commented Jan 25, 2016

This comment has been minimized.

fabxc commented Jan 25, 2016

This comment has been minimized.

RichiH commented Jan 26, 2016

fabxc referenced this issue Jan 26, 2016

Increase notification test timeouts #1348

fabxc changed the title Panic in notification test Timing issues in storage test Jan 26, 2016

This comment has been minimized.

fabxc commented Jan 26, 2016

fabxc assigned beorn7 Jan 26, 2016

beorn7 added the bug label Jan 26, 2016

beorn7 referenced this issue Mar 3, 2016

Give TestEvictAndLoadChunkDescs more time to actually evict #1454

This comment has been minimized.

brian-brazil commented Apr 8, 2016

This comment has been minimized.

beorn7 commented Apr 8, 2016

This comment has been minimized.

beorn7 commented Apr 8, 2016

beorn7 closed this Apr 8, 2016

This comment has been minimized.

lock bot commented Mar 24, 2019

lock bot locked and limited conversation to collaborators Mar 24, 2019