labelblk test failure on linux

[stuarteberg]

As mentioned over Slack, I'm seeing a weird test failure when building DVID within the flyem-build Docker container.

The commands to download the container from scratch and reproduce the failure are as follows.

# Launch the container
git clone https://github.com/janelia-flyem/flyem-build-container
cd flyem-build-container
./launch.sh

# Within the container
source activate dvid-devel
cd /flyem-workspace/gopath/src/github.com/janelia-flyem/dvid
make test

Here's the test failure output:

Click for test log

$ make test
Backend not specified. Using default value: DVID_BACKENDS="basholeveldb filestore gbucket swift"
go build -o bin/dvid-gen-version -v -tags "basholeveldb filestore gbucket swift" cmd/gen-version/main.go
bin/dvid-gen-version -o server/version.go
go build -o bin/dvid -v -tags "basholeveldb filestore gbucket swift" cmd/dvid/main.go
go test  -tags "basholeveldb filestore gbucket swift" github.com/janelia-flyem/dvid/dvid/... github.com/janelia-flyem/dvid/storage/... github.com/janelia-flyem/dvid/datastore github.com/janelia-flyem/dvid/server github.com/janelia-flyem/dvid/datatype/... github.com/janelia-flyem/dvid/tests_integration
ok  	github.com/janelia-flyem/dvid/dvid	(cached)
ok  	github.com/janelia-flyem/dvid/storage	(cached)
?   	github.com/janelia-flyem/dvid/storage/basholeveldb	[no test files]
?   	github.com/janelia-flyem/dvid/storage/filelog	[no test files]
?   	github.com/janelia-flyem/dvid/storage/filestore	[no test files]
?   	github.com/janelia-flyem/dvid/storage/gbucket	[no test files]
?   	github.com/janelia-flyem/dvid/storage/swift	[no test files]
ok  	github.com/janelia-flyem/dvid/datastore	(cached)
ok  	github.com/janelia-flyem/dvid/server	(cached)
?   	github.com/janelia-flyem/dvid/datatype	[no test files]
ok  	github.com/janelia-flyem/dvid/datatype/annotation	(cached)
?   	github.com/janelia-flyem/dvid/datatype/common/downres	[no test files]
ok  	github.com/janelia-flyem/dvid/datatype/common/labels	(cached)
?   	github.com/janelia-flyem/dvid/datatype/common/proto	[no test files]
?   	github.com/janelia-flyem/dvid/datatype/googlevoxels	[no test files]
ok  	github.com/janelia-flyem/dvid/datatype/imageblk	(cached)
ok  	github.com/janelia-flyem/dvid/datatype/imagetile	(cached)
ok  	github.com/janelia-flyem/dvid/datatype/keyvalue	(cached)
ok  	github.com/janelia-flyem/dvid/datatype/labelarray	(cached)
2018/12/09 06:07:55  INFO OpenTest with [[] map[]]: cache setting %!!(MISSING)v(MISSING)
2018/12/09 06:07:55  INFO Opening test datastore.  Create = [true]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Database not already at path ([/tmp/dvid-test-basholeveldb-406e7a25fa1b44b99a9ca9f22897994f]). Creating directory...
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 leveldb cache size: [537MB]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 leveldb write buffer size: [63MB]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Opening basholeveldb @ path [/tmp/dvid-test-basholeveldb-406e7a25fa1b44b99a9ca9f22897994f]
2018/12/09 06:07:55  INFO Log not already at path ([/tmp/dvid-test-filelog-5a71d478e92743d48c9f7b6ce535f8c8]). Creating ...
2018/12/09 06:07:55  INFO File store not already at path ([/tmp/dvid-test-filestore-a46e9f62602949e1bd294f305d2dab12]). Creating ...
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Default kv store: [basholeveldb @ /tmp/dvid-test-basholeveldb-406e7a25fa1b44b99a9ca9f22897994f]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Default log store: [write logs @ /tmp/dvid-test-filelog-5a71d478e92743d48c9f7b6ce535f8c8]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Metadata store: [basholeveldb @ /tmp/dvid-test-basholeveldb-406e7a25fa1b44b99a9ca9f22897994f]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Initializing repo management data in storage...
%!!(MISSING)(EXTRA []interface {}=[])
2018/12/09 06:07:55  INFO Storage initialized.  initMetadata = [true]
2018/12/09 06:07:55  INFO new repo with passcode [foobar]
2018/12/09 06:07:55  INFO Set mutation ID for repo [ff04307cbdfb4f63bfd895e97a59d76c %!!(MISSING)s(uint64=1000000000)] to minimum set: %!!(MISSING)d(MISSING)
2018/12/09 06:07:55  INFO Created and saved new repo ["ff04307cbdfb4f63bfd895e97a59d76c" '\x01'], id %!!(MISSING)d(MISSING)
2018/12/09 06:07:55  INFO Launching sync event handler for data ["mylabels"]...
2018/12/09 06:07:55  INFO Initialized data handlers for instance ["mylabels"] on creating of new data.
2018/12/09 06:07:55  INFO GetVoxels [3d volume of size (96,64,160) @ (32,0,64)]: 9.0184ms
2018/12/09 06:07:55  INFO Shutting down sync event handler for instance ["mylabels"]...
2018/12/09 06:07:55  INFO All [1] data instances shutdown.
2018/12/09 06:07:55  INFO Deleted test engine ["basholeveldb [0.9.0]" {{map["path":"dvid-test-basholeveldb-406e7a25fa1b44b99a9ca9f22897994f" "testing":%!!(MISSING)q(bool=true)]} "basholeveldb"}] with backend %!!(MISSING)q(MISSING)
2018/12/09 06:07:55  INFO Deleted test engine ["filelog [0.1.0]" {{map["path":"dvid-test-filelog-5a71d478e92743d48c9f7b6ce535f8c8" "testing":%!!(MISSING)q(bool=true)]} "filelog"}] with backend %!!(MISSING)q(MISSING)
2018/12/09 06:07:55  INFO Deleted test engine ["filestore [0.1.0]" {{map["path":"dvid-test-filestore-a46e9f62602949e1bd294f305d2dab12" "testing":%!!(MISSING)q(bool=true)]} "filestore"}] with backend %!!(MISSING)q(MISSING)
2018/12/09 06:07:55  INFO OpenTest with [[] map[]]: cache setting %!!(MISSING)v(MISSING)
2018/12/09 06:07:55  INFO Opening test datastore.  Create = [true]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Database not already at path ([/tmp/dvid-test-basholeveldb-557e14aa8e8c444f8690495820924054]). Creating directory...
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 leveldb cache size: [537MB]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 leveldb write buffer size: [63MB]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Opening basholeveldb @ path [/tmp/dvid-test-basholeveldb-557e14aa8e8c444f8690495820924054]
2018/12/09 06:07:55  INFO Log not already at path ([/tmp/dvid-test-filelog-30c5ca12f4b74446bf2f0299a80b40b4]). Creating ...
2018/12/09 06:07:55  INFO File store not already at path ([/tmp/dvid-test-filestore-0ca5c4cf301f44abbc9c7843a41e00e9]). Creating ...
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Default kv store: [basholeveldb @ /tmp/dvid-test-basholeveldb-557e14aa8e8c444f8690495820924054]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Default log store: [write logs @ /tmp/dvid-test-filelog-30c5ca12f4b74446bf2f0299a80b40b4]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Metadata store: [basholeveldb @ /tmp/dvid-test-basholeveldb-557e14aa8e8c444f8690495820924054]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Initializing repo management data in storage...
%!!(MISSING)(EXTRA []interface {}=[])
2018/12/09 06:07:55  INFO Storage initialized.  initMetadata = [true]
2018/12/09 06:07:55  INFO new repo with passcode [foobar]
2018/12/09 06:07:55  INFO Set mutation ID for repo [8d79f147faae40a797dc765dbce2d2a0 %!!(MISSING)s(uint64=1000000000)] to minimum set: %!!(MISSING)d(MISSING)
2018/12/09 06:07:55  INFO Created and saved new repo ["8d79f147faae40a797dc765dbce2d2a0" '\x01'], id %!!(MISSING)d(MISSING)
2018/12/09 06:07:55  INFO Changing resolution of voxels to [1.1,2.8,11]
2018/12/09 06:07:55  INFO Launching sync event handler for data ["mylabels"]...
2018/12/09 06:07:55  INFO Initialized data handlers for instance ["mylabels"] on creating of new data.
2018/12/09 06:07:55  INFO Closing test datastore for reopen test...
%!!(MISSING)(EXTRA []interface {}=[])
2018/12/09 06:07:55  INFO Closing store ["basholeveldb" "basholeveldb @ /tmp/dvid-test-basholeveldb-557e14aa8e8c444f8690495820924054"]: %!!(MISSING)s(MISSING)...
2018/12/09 06:07:55  INFO Closing store ["filelog" "write logs @ /tmp/dvid-test-filelog-30c5ca12f4b74446bf2f0299a80b40b4"]: %!!(MISSING)s(MISSING)...
2018/12/09 06:07:55  INFO Closing store ["filestore" "file store @ /tmp/dvid-test-filestore-0ca5c4cf301f44abbc9c7843a41e00e9"]: %!!(MISSING)s(MISSING)...
2018/12/09 06:07:55  INFO Reopening test datastore...
%!!(MISSING)(EXTRA []interface {}=[])
2018/12/09 06:07:55  INFO Opening test datastore.  Create = [false]
2018/12/09 06:07:55  INFO Found file store at [/tmp/dvid-test-filestore-0ca5c4cf301f44abbc9c7843a41e00e9 <nil>] (err = %!!(MISSING)v(MISSING))
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Found directory at [/tmp/dvid-test-basholeveldb-557e14aa8e8c444f8690495820924054 <nil>] (err = %!!(MISSING)v(MISSING))
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 leveldb cache size: [537MB]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 leveldb write buffer size: [63MB]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Opening basholeveldb @ path [/tmp/dvid-test-basholeveldb-557e14aa8e8c444f8690495820924054]
2018/12/09 06:07:55  INFO Found log at [/tmp/dvid-test-filelog-30c5ca12f4b74446bf2f0299a80b40b4 <nil>] (err = %!!(MISSING)v(MISSING))
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Default kv store: [basholeveldb @ /tmp/dvid-test-basholeveldb-557e14aa8e8c444f8690495820924054]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Default log store: [write logs @ /tmp/dvid-test-filelog-30c5ca12f4b74446bf2f0299a80b40b4]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Metadata store: [basholeveldb @ /tmp/dvid-test-basholeveldb-557e14aa8e8c444f8690495820924054]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Loading metadata from storage...
%!!(MISSING)(EXTRA []interface {}=[])
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Loading metadata with format version [1]...
2018/12/09 06:07:55  INFO Launching sync event handler for data ["mylabels"]...
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Initialized data handlers for instance ["mylabels"] on repo load.
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Loaded [1] repositories from metadata store.
2018/12/09 06:07:55  INFO Loaded mutation ID for repo [8d79f147faae40a797dc765dbce2d2a0 %!!(MISSING)s(uint64=1000000100)]: %!!(MISSING)d(MISSING)
2018/12/09 06:07:55  INFO Storage initialized.  initMetadata = [false]
2018/12/09 06:07:55  INFO Shutting down sync event handler for instance ["mylabels"]...
2018/12/09 06:07:55  INFO All [1] data instances shutdown.
2018/12/09 06:07:55  INFO Deleted test engine ["basholeveldb [0.9.0]" {{map["path":"dvid-test-basholeveldb-557e14aa8e8c444f8690495820924054" "testing":%!!(MISSING)q(bool=true)]} "basholeveldb"}] with backend %!!(MISSING)q(MISSING)
2018/12/09 06:07:55  INFO Deleted test engine ["filelog [0.1.0]" {{map["testing":%!!(MISSING)q(bool=true) "path":"dvid-test-filelog-30c5ca12f4b74446bf2f0299a80b40b4"]} "filelog"}] with backend %!!(MISSING)q(MISSING)
2018/12/09 06:07:55  INFO Deleted test engine ["filestore [0.1.0]" {{map["path":"dvid-test-filestore-0ca5c4cf301f44abbc9c7843a41e00e9" "testing":%!!(MISSING)q(bool=true)]} "filestore"}] with backend %!!(MISSING)q(MISSING)
2018/12/09 06:07:55  INFO OpenTest with [[] map[]]: cache setting %!!(MISSING)v(MISSING)
2018/12/09 06:07:55  INFO Opening test datastore.  Create = [true]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Database not already at path ([/tmp/dvid-test-basholeveldb-a3c3486b7ab04d26914dc8e026231fdf]). Creating directory...
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 leveldb cache size: [537MB]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 leveldb write buffer size: [63MB]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Opening basholeveldb @ path [/tmp/dvid-test-basholeveldb-a3c3486b7ab04d26914dc8e026231fdf]
2018/12/09 06:07:55  INFO Log not already at path ([/tmp/dvid-test-filelog-c0893651586347e9a222e24c4f6131ff]). Creating ...
2018/12/09 06:07:55  INFO File store not already at path ([/tmp/dvid-test-filestore-bfc6c74fc271434e935b0ff042637e39]). Creating ...
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Default kv store: [basholeveldb @ /tmp/dvid-test-basholeveldb-a3c3486b7ab04d26914dc8e026231fdf]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Default log store: [write logs @ /tmp/dvid-test-filelog-c0893651586347e9a222e24c4f6131ff]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Metadata store: [basholeveldb @ /tmp/dvid-test-basholeveldb-a3c3486b7ab04d26914dc8e026231fdf]
2018/12/09 06:07:55  INFO 2018/12/09 06:07:55 Initializing repo management data in storage...
%!!(MISSING)(EXTRA []interface {}=[])
2018/12/09 06:07:55  INFO Storage initialized.  initMetadata = [true]
2018/12/09 06:07:55  INFO new repo with passcode [foobar]
2018/12/09 06:07:55  INFO Set mutation ID for repo [f72f6d200fac4590a51d35a8d1350a4c %!!(MISSING)s(uint64=1000000000)] to minimum set: %!!(MISSING)d(MISSING)
2018/12/09 06:07:55  INFO Created and saved new repo ["f72f6d200fac4590a51d35a8d1350a4c" '\x01'], id %!!(MISSING)d(MISSING)
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000001] Started POST "/api/repo/f72f6d200fac4590a51d35a8d1350a4c/instance" from
2018/12/09 06:07:55  INFO Launching sync event handler for data ["labels"]...
2018/12/09 06:07:55  INFO Initialized data handlers for instance ["labels"] on creating of new data.
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000001] Returning 200 in 539.4µs
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000002] Started POST "/api/repo/f72f6d200fac4590a51d35a8d1350a4c/instance" from
2018/12/09 06:07:55  INFO Launching sync event handler for data ["labels_1"]...
2018/12/09 06:07:55  INFO Initialized data handlers for instance ["labels_1"] on creating of new data.
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000002] Returning 200 in 463.2µs
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000003] Started POST "/api/node/f72f6d200fac4590a51d35a8d1350a4c/labels_1/sync" from
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000003] Returning 200 in 306.2µs
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000004] Started POST "/api/repo/f72f6d200fac4590a51d35a8d1350a4c/instance" from
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000004] Returning 200 in 391µs
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000005] Started POST "/api/node/f72f6d200fac4590a51d35a8d1350a4c/labels_2/sync" from
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000005] Returning 200 in 332.8µs
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000006] Started POST "/api/node/f72f6d200fac4590a51d35a8d1350a4c/labels/raw/0_1_2/128_128_128/0_0_0" from
2018/12/09 06:07:55  INFO Launching sync event handler for data ["labels_2"]...
2018/12/09 06:07:55  INFO Initialized data handlers for instance ["labels_2"] on creating of new data.
2018/12/09 06:07:55 [bc24be41163f/RuvjCrauNa-000006] Returning 200 in 58.6297ms
2018/12/09 06:07:55  INFO HTTP [POST 3d volume (128,128,128) at offset (0,0,0) /api/node/f72f6d200fac4590a51d35a8d1350a4c/labels/raw/0_1_2/128_128_128/0_0_0]: 58.5619ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000007] Started GET "/api/node/f72f6d200fac4590a51d35a8d1350a4c/labels/raw/0_1_2/128_128_128/0_0_0" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000007] Returning 200 in 23.3699ms
2018/12/09 06:07:56  INFO HTTP [GET 3d volume (128,128,128) at offset (0,0,0) /api/node/f72f6d200fac4590a51d35a8d1350a4c/labels/raw/0_1_2/128_128_128/0_0_0]: 23.115ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000008] Started GET "/api/node/f72f6d200fac4590a51d35a8d1350a4c/labels_1/raw/0_1_2/64_64_64/0_0_0" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000008] Returning 200 in 3.3881ms
2018/12/09 06:07:56  INFO HTTP [GET 3d volume (64,64,64) at offset (0,0,0) /api/node/f72f6d200fac4590a51d35a8d1350a4c/labels_1/raw/0_1_2/64_64_64/0_0_0]: 3.3154ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000009] Started GET "/api/node/f72f6d200fac4590a51d35a8d1350a4c/labels_2/raw/0_1_2/32_32_32/0_0_0" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000009] Returning 200 in 658.9µs
2018/12/09 06:07:56  INFO HTTP [GET 3d volume (32,32,32) at offset (0,0,0) /api/node/f72f6d200fac4590a51d35a8d1350a4c/labels_2/raw/0_1_2/32_32_32/0_0_0]: 579.2µs (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56  INFO Shutting down sync event handler for instance ["labels_1"]...
2018/12/09 06:07:56  INFO Shutting down sync event handler for instance ["labels_2"]...
2018/12/09 06:07:56  INFO Shutting down sync event handler for instance ["labels"]...
2018/12/09 06:07:56  INFO All [3] data instances shutdown.
2018/12/09 06:07:56  INFO Deleted test engine ["basholeveldb [0.9.0]" {{map["path":"dvid-test-basholeveldb-a3c3486b7ab04d26914dc8e026231fdf" "testing":%!!(MISSING)q(bool=true)]} "basholeveldb"}] with backend %!!(MISSING)q(MISSING)
2018/12/09 06:07:56  INFO Deleted test engine ["filelog [0.1.0]" {{map["path":"dvid-test-filelog-c0893651586347e9a222e24c4f6131ff" "testing":%!!(MISSING)q(bool=true)]} "filelog"}] with backend %!!(MISSING)q(MISSING)
2018/12/09 06:07:56  INFO Deleted test engine ["filestore [0.1.0]" {{map["path":"dvid-test-filestore-bfc6c74fc271434e935b0ff042637e39" "testing":%!!(MISSING)q(bool=true)]} "filestore"}] with backend %!!(MISSING)q(MISSING)
2018/12/09 06:07:56  INFO OpenTest with [[] map[]]: cache setting %!!(MISSING)v(MISSING)
2018/12/09 06:07:56  INFO Opening test datastore.  Create = [true]
2018/12/09 06:07:56  INFO 2018/12/09 06:07:56 Database not already at path ([/tmp/dvid-test-basholeveldb-9d8df5fdce2f4a36afee8501bf1b2ef5]). Creating directory...
2018/12/09 06:07:56  INFO 2018/12/09 06:07:56 leveldb cache size: [537MB]
2018/12/09 06:07:56  INFO 2018/12/09 06:07:56 leveldb write buffer size: [63MB]
2018/12/09 06:07:56  INFO 2018/12/09 06:07:56 Opening basholeveldb @ path [/tmp/dvid-test-basholeveldb-9d8df5fdce2f4a36afee8501bf1b2ef5]
2018/12/09 06:07:56  INFO Log not already at path ([/tmp/dvid-test-filelog-d0d6b88c1d4b4816bf68165eef095542]). Creating ...
2018/12/09 06:07:56  INFO File store not already at path ([/tmp/dvid-test-filestore-c979c555179141c4af376911ecee7612]). Creating ...
2018/12/09 06:07:56  INFO 2018/12/09 06:07:56 Default kv store: [basholeveldb @ /tmp/dvid-test-basholeveldb-9d8df5fdce2f4a36afee8501bf1b2ef5]
2018/12/09 06:07:56  INFO 2018/12/09 06:07:56 Default log store: [write logs @ /tmp/dvid-test-filelog-d0d6b88c1d4b4816bf68165eef095542]
2018/12/09 06:07:56  INFO 2018/12/09 06:07:56 Metadata store: [basholeveldb @ /tmp/dvid-test-basholeveldb-9d8df5fdce2f4a36afee8501bf1b2ef5]
2018/12/09 06:07:56  INFO 2018/12/09 06:07:56 Initializing repo management data in storage...
%!!(MISSING)(EXTRA []interface {}=[])
2018/12/09 06:07:56  INFO Storage initialized.  initMetadata = [true]
2018/12/09 06:07:56  INFO new repo with passcode [foobar]
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000010] Started POST "/api/repo/66713564846a44ccb83e5e35daf5186d/instance" from
2018/12/09 06:07:56  INFO Set mutation ID for repo [66713564846a44ccb83e5e35daf5186d %!!(MISSING)s(uint64=1000000000)] to minimum set: %!!(MISSING)d(MISSING)
2018/12/09 06:07:56  INFO Created and saved new repo ["66713564846a44ccb83e5e35daf5186d" '\x01'], id %!!(MISSING)d(MISSING)
2018/12/09 06:07:56  INFO Launching sync event handler for data ["labels"]...
2018/12/09 06:07:56  INFO Initialized data handlers for instance ["labels"] on creating of new data.
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000010] Returning 200 in 354.7µs
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000011] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000011] Returning 200 in 92.7205ms
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000012] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/blocks/160_32_32/32_64_96" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000012] Returning 200 in 711.3µs
Got 658821 bytes of data
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000013] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/blocks/160_32_32/32_64_96?compression=uncompressed" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000013] Returning 200 in 2.4425ms
Got 1310800 bytes of data
2018/12/09 06:07:56  INFO HTTP [POST 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96]: 92.6215ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56  INFO SendBlocks [(1,2,3) %!!(MISSING)s(int32=5) %!!(MISSING)s(int32=1) %!!(MISSING)s(int32=1)], span x 634900, span y %!!(MISSING)d(MISSING), span z %!!(MISSING)d(MISSING): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56  INFO HTTP [GET 3d volume (160,32,32) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/blocks/160_32_32/32_64_96]: 665.7µs (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56  INFO SendBlocks [(1,2,3) %!!(MISSING)s(int32=5) %!!(MISSING)s(int32=1) %!!(MISSING)s(int32=1)], span x 2235700, span y %!!(MISSING)d(MISSING), span z %!!(MISSING)d(MISSING): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56  INFO HTTP [GET 3d volume (160,32,32) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/blocks/160_32_32/32_64_96?compression=uncompressed]: 2.2715ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000014] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/label/100_64_96" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000014] Returning 200 in 626.5µs
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000015] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/label/10000_64000_9600121" from
2018/12/09 06:07:56  INFO HTTP [GET (100,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/label/100_64_96]: label at 443.4µs (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000015] Returning 200 in 104µs
2018/12/09 06:07:56  INFO HTTP [GET (10000,64000,9600121) /api/node/66713564846a44ccb83e5e35daf5186d/labels/label/10000_64000_9600121]: label at 61.4µs (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000016] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/labels" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000016] Returning 200 in 1.6456ms
2018/12/09 06:07:56  INFO HTTP batch label-at-point query ([3] coordinates): 1.5861ms
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000017] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000017] Returning 200 in 105.7744ms
2018/12/09 06:07:56  INFO HTTP [POST 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96]: 105.6313ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000018] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000018] Returning 200 in 123.5719ms
2018/12/09 06:07:56  INFO HTTP [POST 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96]: 123.474ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000019] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000019] Returning 200 in 125.6922ms
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000020] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/xy/67_83/83_75_119" from
2018/12/09 06:07:56  INFO HTTP [POST 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96]: 125.5411ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000020] Returning 200 in 4.3139ms
2018/12/09 06:07:56  INFO HTTP [GET XY slice /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/xy/67_83/83_75_119]: 4.2409ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000021] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/xz/67_83/43_68_99" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000021] Returning 200 in 6.2706ms
2018/12/09 06:07:56  INFO HTTP [GET XZ slice /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/xz/67_83/43_68_99]: 6.1885ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000022] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/yz/67_83/39_97_129" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000022] Returning 200 in 4.9253ms
2018/12/09 06:07:56  INFO HTTP [GET YZ slice /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/yz/67_83/39_97_129]: 4.8469ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000023] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000024] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000025] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96" from
2018/12/09 06:07:56 [bc24be41163f/RuvjCrauNa-000023] Returning 200 in 89.4346ms
2018/12/09 06:07:56  INFO HTTP [POST 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96]: 89.3122ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000024] Returning 200 in 209.8025ms
2018/12/09 06:07:57  INFO HTTP [POST 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96]: 209.0438ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000025] Returning 200 in 278.619ms
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000026] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96" from
2018/12/09 06:07:57  INFO HTTP [POST 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96]: 278.5315ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000026] Returning 200 in 73.2467ms
2018/12/09 06:07:57  INFO HTTP [GET 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96]: 73.1615ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000027] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/192_64_96?compression=lz4" from
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000028] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_224_96?compression=lz4" from
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000029] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/192_224_96?compression=lz4" from
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000028] Returning 200 in 192.9225ms
2018/12/09 06:07:57  INFO HTTP [POST 3d volume (160,160,160) at offset (32,224,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_224_96?compression=lz4]: 192.785ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000027] Returning 200 in 293.1289ms
2018/12/09 06:07:57  INFO HTTP [POST 3d volume (160,160,160) at offset (192,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/192_64_96?compression=lz4]: 292.8887ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000029] Returning 200 in 369.1558ms
2018/12/09 06:07:57  INFO HTTP [POST 3d volume (160,160,160) at offset (192,224,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/192_224_96?compression=lz4]: 368.9803ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000030] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96" from
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000030] Returning 200 in 75.0075ms
2018/12/09 06:07:57  INFO HTTP [GET 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96]: 74.9037ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000031] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/192_64_96" from
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000031] Returning 200 in 109.427ms
2018/12/09 06:07:57  INFO HTTP [GET 3d volume (160,160,160) at offset (192,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/192_64_96]: 109.1854ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000032] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/192_224_96" from
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000032] Returning 200 in 85.7638ms
2018/12/09 06:07:57  INFO HTTP [GET 3d volume (160,160,160) at offset (192,224,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/192_224_96]: 85.6526ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000033] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_224_96" from
2018/12/09 06:07:57 [bc24be41163f/RuvjCrauNa-000033] Returning 200 in 76.5184ms
2018/12/09 06:07:57  INFO HTTP [GET 3d volume (160,160,160) at offset (32,224,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_224_96]: 76.4164ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:58 [bc24be41163f/RuvjCrauNa-000034] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96" from
2018/12/09 06:07:58 [bc24be41163f/RuvjCrauNa-000034] Returning 200 in 181.1977ms
2018/12/09 06:07:58  INFO HTTP [GET 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96]: 181.0835ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:58 [bc24be41163f/RuvjCrauNa-000035] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96?compression=lz4" from
2018/12/09 06:07:58 [bc24be41163f/RuvjCrauNa-000035] Returning 200 in 530.5242ms
2018/12/09 06:07:58  INFO HTTP [GET 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96?compression=lz4]: 517.7703ms (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:07:59 [bc24be41163f/RuvjCrauNa-000036] Started GET "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96?compression=gzip" from
2018/12/09 06:08:04 [bc24be41163f/RuvjCrauNa-000036] Returning 200 in 4.7247913s
2018/12/09 06:08:04  INFO HTTP [GET 3d volume (160,160,160) at offset (32,64,96) /api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96?compression=gzip]: 4.7162991s (%!!(MISSING)s(MISSING)): %!!(MISSING)s(MISSING)
2018/12/09 06:08:05 [bc24be41163f/RuvjCrauNa-000037] Started POST "/api/repo/66713564846a44ccb83e5e35daf5186d/instance" from
2018/12/09 06:08:05 [bc24be41163f/RuvjCrauNa-000037] Returning 200 in 34.7976ms
2018/12/09 06:08:05 [bc24be41163f/RuvjCrauNa-000038] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/myroi/roi" from
2018/12/09 06:08:05 [bc24be41163f/RuvjCrauNa-000038] Returning 200 in 7.3405ms
2018/12/09 06:08:05  INFO HTTP POST ROI "myroi": 61 bytes: []
%!!(MISSING)(EXTRA time.Duration=6.9079ms)
2018/12/09 06:08:06 [bc24be41163f/RuvjCrauNa-000039] Started POST "/api/node/66713564846a44ccb83e5e35daf5186d/labels/raw/0_1_2/160_160_160/32_64_96" from
FAIL	github.com/janelia-flyem/dvid/datatype/labelblk	59.862s
ok  	github.com/janelia-flyem/dvid/datatype/labelgraph	(cached)
ok  	github.com/janelia-flyem/dvid/datatype/labelmap	84.793s
ok  	github.com/janelia-flyem/dvid/datatype/labelsz	65.249s
ok  	github.com/janelia-flyem/dvid/datatype/labelvol	(cached)
ok  	github.com/janelia-flyem/dvid/datatype/multichan16	(cached)
ok  	github.com/janelia-flyem/dvid/datatype/roi	(cached)
ok  	github.com/janelia-flyem/dvid/datatype/tarsupervoxels	(cached)
ok  	github.com/janelia-flyem/dvid/tests_integration	(cached)
make: *** [test] Error 1

[stuarteberg]

BTW, it isn't obvious what is causing the failure from the test log, but the log does indicate that some calls to Sprintf() failed. For example:

%!!(MISSING)(EXTRA []interface {}=[])

Just in case those missing log messages might contain the clue to the labelblk test failure, maybe it's best to fix the Sprintf calls first and then re-run the test suite.

[DocSavage]

A fix to the comment system was committed. Maybe it's the actual logging system causing the error for some Go versions?

[stuarteberg]

I've discovered an issue with the test suite: If I run make test I see a failure, but then if I run it a second time, it "passes"... except that the failed test is merely skipped. Somehow, the test suite thinks the test is cached, and just skips it.

I can force the tests to run via GOCACHE=off make test, which triggers the error once more.

So... in your setup, does it matter if you use GOCACHE-off make test? Does that enable you to reproduce the failure on your own machine?

[stuarteberg]

I found the issue, kinda.

I had recently re-installed Docker for Mac on my laptop, and that's when this trouble began. It turns out that the default RAM allocation for the Docker Engine is only 2 GB, and -- apparently -- that causes random errors like the one shown above. When I increased the RAM for Docker to 4 GB, everything works smoothly and I can no longer reproduce the test failure.

Very strange, but oh well, at least it's fixed now!