Actions
Bug #12822
closed
[keepproxy] regression: cannot read data with a collection-sharing token
Story points:
-
Description
keepproxy validates tokens by calling the /users/current API. But a collection-sharing token doesn't have /users/current in scopes. Until recently we had a bug that made /users/current succeed when the anonymous token was passed. Now that that's fixed, keepproxy is broken.
Checking /keep_services/accessible instead of /users/current should fix this.
Updated by Tom Clegg over 6 years ago
- Status changed from New to In Progress
- Assigned To set to Tom Clegg
- Target version set to 2017-12-20 Sprint
12822-keepproxy-token-scope @ e112475459e4cab53cac0121606bc895efeb5ae5
Updated by Peter Amstutz over 6 years ago
Getting lots of test failures:
----------------------------------------------------------------------
PANIC: keepproxy_test.go:532: ServerRequiredSuite.TestCollectionSharingToken
keepproxy_test.go:536:
c.Check(err, IsNil)
... value *errors.errorString = &errors.errorString{s:"Could not write sufficient replicas: [0] "} ("Could not write sufficient replicas: [0] ")
... Panic: runtime error: slice bounds out of range (PC=0x458DC8)
/usr/local/go/src/runtime/panic.go:489
in gopanic
/usr/local/go/src/runtime/panic.go:35
in panicslice
/var/lib/arvados/test/GOPATH/src/git.curoverse.com/arvados.git/sdk/go/keepclient/keepclient.go:436
in KeepClient.getSortedRoots
/var/lib/arvados/test/GOPATH/src/git.curoverse.com/arvados.git/sdk/go/keepclient/keepclient.go:207
in KeepClient.getOrHead
/var/lib/arvados/test/GOPATH/src/git.curoverse.com/arvados.git/sdk/go/keepclient/keepclient.go:293
in KeepClient.Get
keepproxy_test.go:538
in ServerRequiredSuite.TestCollectionSharingToken
/usr/local/go/src/reflect/value.go:302
in Value.Call
/usr/local/go/src/runtime/asm_amd64.s:2197
in goexit
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:00.805848045Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:00.805889729Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:00.806086534Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:00.806098510Z"}
{"level":"info","msg":"Listening at [::]:43609","time":"2017-12-15T14:34:00.829858660Z"}
----------------------------------------------------------------------
PANIC: keepproxy_test.go:399: ServerRequiredSuite.TestCorsHeaders
keepproxy_test.go:411:
c.Check(err, Equals, nil)
... obtained *url.Error = &url.Error{Op:"Options", URL:"http://[::]:43609/acbd18db4cc2f85cedef654fccc4a4d8+3", Err:(*net.OpError)(0xc4203d2500)} ("Options http://[::]:43609/acbd18db4cc2f85cedef654fccc4a4d8+3: dial tcp [::]:43609: connect: cannot assign requested address")
... expected = nil
... Panic: runtime error: invalid memory address or nil pointer dereference (PC=0x458DC8)
/usr/local/go/src/runtime/panic.go:489
in gopanic
/usr/local/go/src/runtime/panic.go:63
in panicmem
/usr/local/go/src/runtime/signal_unix.go:290
in sigpanic
keepproxy_test.go:412
in ServerRequiredSuite.TestCorsHeaders
/usr/local/go/src/reflect/value.go:302
in Value.Call
/usr/local/go/src/runtime/asm_amd64.s:2197
in goexit
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:00.856839118Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:00.857009390Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:00.857217368Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:00.857230552Z"}
{"level":"info","msg":"Listening at [::]:45677","time":"2017-12-15T14:34:00.880656378Z"}
----------------------------------------------------------------------
FAIL: keepproxy_test.go:164: ServerRequiredSuite.TestDesiredReplicas
keepproxy_test.go:173:
c.Check(err, Equals, nil)
... obtained *errors.errorString = &errors.errorString{s:"Could not write sufficient replicas: [0] "} ("Could not write sufficient replicas: [0] ")
... expected = nil
keepproxy_test.go:174:
c.Check(rep, Equals, kc.Want_replicas)
... obtained int = 0
... expected int = 1
keepproxy_test.go:173:
c.Check(err, Equals, nil)
... obtained *errors.errorString = &errors.errorString{s:"Could not write sufficient replicas: [0] "} ("Could not write sufficient replicas: [0] ")
... expected = nil
keepproxy_test.go:174:
c.Check(rep, Equals, kc.Want_replicas)
... obtained int = 0
... expected int = 2
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:00.911110703Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:00.911333654Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: true\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:00.911553520Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:00.911568252Z"}
{"level":"info","msg":"Listening at [::]:42359","time":"2017-12-15T14:34:00.934674059Z"}
----------------------------------------------------------------------
FAIL: keepproxy_test.go:348: ServerRequiredSuite.TestGetDisabled
keepproxy_test.go:358:
c.Assert(strings.Contains(err.Error(), "HTTP 400"), Equals, true)
... obtained bool = false
... expected bool = true
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:00.962658545Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:00.962748554Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:00.962958201Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:00.962973511Z"}
{"level":"info","msg":"Listening at [::]:41135","time":"2017-12-15T14:34:00.984880925Z"}
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:01.018485791Z"}
----------------------------------------------------------------------
FAIL: keepproxy_test.go:470: ServerRequiredSuite.TestGetIndex
keepproxy_test.go:479:
c.Check(hash2, Matches, fmt.Sprintf(`^%s\+10(\+.+)?$`, hash))
... value string = ""
... regex string = "^07d16262005bf7084baeaf714576f600\\+10(\\+.+)?$"
keepproxy_test.go:480:
c.Check(rep, Equals, 2)
... obtained int = 0
... expected int = 2
keepproxy_test.go:481:
c.Check(err, Equals, nil)
... obtained *errors.errorString = &errors.errorString{s:"Could not write sufficient replicas: [0] "} ("Could not write sufficient replicas: [0] ")
... expected = nil
keepproxy_test.go:484:
c.Assert(err, Equals, nil)
... obtained *keepclient.ErrNotFound = &keepclient.ErrNotFound{multipleResponseError:keepclient.multipleResponseError{error:(*errors.errorString)(0xc4202ba240), isTemp:true}} ("GET 07d16262005bf7084baeaf714576f600 failed: [http://[::]:41135/07d16262005bf7084baeaf714576f600: Get http://[::]:41135/07d16262005bf7084baeaf714576f600: dial tcp [::]:41135: connect: cannot assign requested address http://[::]:41135/07d16262005bf7084baeaf714576f600: Get http://[::]:41135/07d16262005bf7084baeaf714576f600: dial tcp [::]:41135: connect: cannot assign requested address http://[::]:41135/07d16262005bf7084baeaf714576f600: Get http://[::]:41135/07d16262005bf7084baeaf714576f600: dial tcp [::]:41135: connect: cannot assign requested address]")
... expected = nil
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:01.019446799Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:01.019680676Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:01.019695140Z"}
{"level":"info","msg":"Listening at [::]:37039","time":"2017-12-15T14:34:01.042181228Z"}
----------------------------------------------------------------------
FAIL: keepproxy_test.go:146: ServerRequiredSuite.TestLoopDetection
keepproxy_test.go:157:
c.Check(err, ErrorMatches, `.*loop detected.*`)
... error string = "Could not write sufficient replicas: [0] "
... regex string = ".*loop detected.*"
keepproxy_test.go:161:
c.Check(err, ErrorMatches, `.*loop detected.*`)
... error string = "GET 628b41cd0c7a69bd3ca83211966e4759 failed: [http://[::]:37039/628b41cd0c7a69bd3ca83211966e4759: Get http://[::]:37039/628b41cd0c7a69bd3ca83211966e4759: dial tcp [::]:37039: connect: cannot assign requested address http://[::]:37039/628b41cd0c7a69bd3ca83211966e4759: Get http://[::]:37039/628b41cd0c7a69bd3ca83211966e4759: dial tcp [::]:37039: connect: cannot assign requested address http://[::]:37039/628b41cd0c7a69bd3ca83211966e4759: Get http://[::]:37039/628b41cd0c7a69bd3ca83211966e4759: dial tcp [::]:37039: connect: cannot assign requested address]"
... regex string = ".*loop detected.*"
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:01.071915794Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:01.072067614Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:01.072261377Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:01.072273872Z"}
{"level":"info","msg":"Listening at [::]:42861","time":"2017-12-15T14:34:01.097091944Z"}
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:01.203652568Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:01.203745091Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:01.203939761Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:01.203953265Z"}
{"level":"info","msg":"Listening at [::]:41345","time":"2017-12-15T14:34:01.227701038Z"}
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:01.262260962Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:01.262351448Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:01.262540942Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:01.262554934Z"}
{"level":"info","msg":"Listening at [::]:40639","time":"2017-12-15T14:34:01.288041633Z"}
----------------------------------------------------------------------
PANIC: keepproxy_test.go:428: ServerRequiredSuite.TestPostWithoutHash
keepproxy_test.go:440:
c.Check(err, Equals, nil)
... obtained *url.Error = &url.Error{Op:"Post", URL:"http://[::]:40639/", Err:(*net.OpError)(0xc4203d25a0)} ("Post http://[::]:40639/: dial tcp [::]:40639: connect: cannot assign requested address")
... expected = nil
... Panic: runtime error: invalid memory address or nil pointer dereference (PC=0x458DC8)
/usr/local/go/src/runtime/panic.go:489
in gopanic
/usr/local/go/src/runtime/panic.go:63
in panicmem
/usr/local/go/src/runtime/signal_unix.go:290
in sigpanic
keepproxy_test.go:441
in ServerRequiredSuite.TestPostWithoutHash
/usr/local/go/src/reflect/value.go:302
in Value.Call
/usr/local/go/src/runtime/asm_amd64.s:2197
in goexit
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:01.317436886Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:01.317638898Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:01.317850782Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:01.317863828Z"}
{"level":"info","msg":"Listening at [::]:41141","time":"2017-12-15T14:34:01.343102939Z"}
----------------------------------------------------------------------
PANIC: keepproxy_test.go:247: ServerRequiredSuite.TestPutAskGet
keepproxy_test.go:256:
c.Check(err, Equals, keepclient.BlockNotFound)
... obtained *keepclient.ErrNotFound = &keepclient.ErrNotFound{multipleResponseError:keepclient.multipleResponseError{error:(*errors.errorString)(0xc420a6d260), isTemp:true}} ("HEAD acbd18db4cc2f85cedef654fccc4a4d8 failed: [http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: Head http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:41141: connect: cannot assign requested address http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: Head http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:41141: connect: cannot assign requested address http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: Head http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:41141: connect: cannot assign requested address]")
... expected *keepclient.ErrNotFound = &keepclient.ErrNotFound{multipleResponseError:keepclient.multipleResponseError{error:(*errors.errorString)(0xc4200f5500), isTemp:false}} ("Block not found")
Finished Ask (expected BlockNotFound)
keepproxy_test.go:263:
c.Check(err, Equals, keepclient.BlockNotFound)
... obtained *keepclient.ErrNotFound = &keepclient.ErrNotFound{multipleResponseError:keepclient.multipleResponseError{error:(*errors.errorString)(0xc420a50840), isTemp:true}} ("GET acbd18db4cc2f85cedef654fccc4a4d8 failed: [http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: Get http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:41141: connect: cannot assign requested address http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: Get http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:41141: connect: cannot assign requested address http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: Get http://[::]:41141/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:41141: connect: cannot assign requested address]")
... expected *keepclient.ErrNotFound = &keepclient.ErrNotFound{multipleResponseError:keepclient.multipleResponseError{error:(*errors.errorString)(0xc4200f5500), isTemp:false}} ("Block not found")
Finished Get (expected BlockNotFound)
keepproxy_test.go:280:
c.Check(hash2, Matches, fmt.Sprintf(`^%s\+3(\+.+)?$`, hash))
... value string = ""
... regex string = "^acbd18db4cc2f85cedef654fccc4a4d8\\+3(\\+.+)?$"
keepproxy_test.go:281:
c.Check(rep, Equals, 2)
... obtained int = 0
... expected int = 2
keepproxy_test.go:282:
c.Check(err, Equals, nil)
... obtained *errors.errorString = &errors.errorString{s:"Could not write sufficient replicas: [0] "} ("Could not write sufficient replicas: [0] ")
... expected = nil
Finished PutB (expected success)
... Panic: runtime error: slice bounds out of range (PC=0x458DC8)
/usr/local/go/src/runtime/panic.go:489
in gopanic
/usr/local/go/src/runtime/panic.go:35
in panicslice
/var/lib/arvados/test/GOPATH/src/git.curoverse.com/arvados.git/sdk/go/keepclient/keepclient.go:436
in KeepClient.getSortedRoots
/var/lib/arvados/test/GOPATH/src/git.curoverse.com/arvados.git/sdk/go/keepclient/keepclient.go:207
in KeepClient.getOrHead
/var/lib/arvados/test/GOPATH/src/git.curoverse.com/arvados.git/sdk/go/keepclient/keepclient.go:310
in KeepClient.Ask
keepproxy_test.go:287
in ServerRequiredSuite.TestPutAskGet
/usr/local/go/src/reflect/value.go:302
in Value.Call
/usr/local/go/src/runtime/asm_amd64.s:2197
in goexit
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:01.379895176Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:01.379930078Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:01.380168089Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:01.380180992Z"}
{"level":"info","msg":"Listening at [::]:40651","time":"2017-12-15T14:34:01.402651643Z"}
----------------------------------------------------------------------
FAIL: keepproxy_test.go:322: ServerRequiredSuite.TestPutAskGetForbidden
keepproxy_test.go:338:
c.Check(err, ErrorMatches, ".*not found.*")
... error string = "HEAD 37b51d194a7513e45b56f6524f2d51f2+3 failed: [http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: Head http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: dial tcp [::]:40651: connect: cannot assign requested address http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: Head http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: dial tcp [::]:40651: connect: cannot assign requested address http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: Head http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: dial tcp [::]:40651: connect: cannot assign requested address]"
... regex string = ".*not found.*"
keepproxy_test.go:343:
c.Check(err, ErrorMatches, ".*not found.*")
... error string = "GET 37b51d194a7513e45b56f6524f2d51f2+3 failed: [http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: Get http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: dial tcp [::]:40651: connect: cannot assign requested address http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: Get http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: dial tcp [::]:40651: connect: cannot assign requested address http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: Get http://[::]:40651/37b51d194a7513e45b56f6524f2d51f2+3: dial tcp [::]:40651: connect: cannot assign requested address]"
... regex string = ".*not found.*"
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:01.429302993Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:01.429395103Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:01.429590167Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:01.429603128Z"}
{"level":"info","msg":"Listening at [::]:36851","time":"2017-12-15T14:34:01.453866509Z"}
----------------------------------------------------------------------
FAIL: keepproxy_test.go:545: ServerRequiredSuite.TestPutAskGetInvalidToken
keepproxy_test.go:551:
c.Check(err, IsNil)
... value *errors.errorString = &errors.errorString{s:"Could not write sufficient replicas: [0] "} ("Could not write sufficient replicas: [0] ")
keepproxy_test.go:552:
c.Check(rep, Equals, 2)
... obtained int = 0
... expected int = 2
keepproxy_test.go:578:
c.Check(err, ErrorMatches, ".*403.*Missing or invalid Authorization header")
... error string = "Could not write sufficient replicas: [0] "
... regex string = ".*403.*Missing or invalid Authorization header"
keepproxy_test.go:578:
c.Check(err, ErrorMatches, ".*403.*Missing or invalid Authorization header")
... error string = "Could not write sufficient replicas: [0] "
... regex string = ".*403.*Missing or invalid Authorization header"
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:01.482842825Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:01.482933386Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: true\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:01.483116147Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:01.483129898Z"}
{"level":"info","msg":"Listening at [::]:37031","time":"2017-12-15T14:34:01.507777207Z"}
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:01.535676250Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:01.535866292Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:01.536067452Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:01.536082844Z"}
{"level":"info","msg":"Listening at [::]:39265","time":"2017-12-15T14:34:01.561045844Z"}
{"level":"info","msg":" PUT /cc994be4c6890a7564e87e4fe4eeaaf0+25 400 1 2 0 - Locator size hint does not match Content-Length header","time":"2017-12-15T14:34:01.586630453Z"}
{"level":"info","msg":" PUT /cc994be4c6890a7564e87e4fe4eeaaf0+25 411 0 2 0 - Length Required","time":"2017-12-15T14:34:01.586674422Z"}
{"level":"info","msg":" PUT /cc994be4c6890a7564e87e4fe4eeaaf0+25 411 -1 2 0 - Length Required","time":"2017-12-15T14:34:01.586707515Z"}
{"level":"info","msg":" PUT /cc994be4c6890a7564e87e4fe4eeaaf0+25 411 0 2 0 - Length Required","time":"2017-12-15T14:34:01.586931227Z"}
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:01.587013517Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:01.587152860Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:01.587336533Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:01.587348127Z"}
{"level":"info","msg":"Listening at [::]:41289","time":"2017-12-15T14:34:01.612187143Z"}
----------------------------------------------------------------------
FAIL: keepproxy_test.go:121: ServerRequiredSuite.TestResponseViaHeader
keepproxy_test.go:130:
c.Assert(err, Equals, nil)
... obtained *url.Error = &url.Error{Op:"Post", URL:"http://[::]:41289/", Err:(*net.OpError)(0xc42001a1e0)} ("Post http://[::]:41289/: dial tcp [::]:41289: connect: cannot assign requested address")
... expected = nil
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:01.639712740Z"}
Sent SIGTERM to 1909 (/usr/src/arvados/tmp/keep0.pid)
[keep0] {"level":"info","msg":"caught signal: terminated","time":"2017-12-15T14:34:01.838577731Z"}
[keep0] {"level":"info","msg":"keepstore exiting, pid 1909","time":"2017-12-15T14:34:01.838682115Z"}
Sent SIGTERM to 1922 (/usr/src/arvados/tmp/keep1.pid)
[keep1] {"level":"info","msg":"caught signal: terminated","time":"2017-12-15T14:34:01.939049219Z"}
[keep1] {"level":"info","msg":"keepstore exiting, pid 1922","time":"2017-12-15T14:34:01.939133655Z"}
2017/12/15 14:34:03 authSettings: map[ARVADOS_API_TOKEN:4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h ARVADOS_API_HOST:0.0.0.0:56621 ARVADOS_API_HOST_INSECURE:true]
[keep0] time="2017-12-15T14:34:04Z" level=info msg="keepstore dev started"
[keep0] {"level":"info","msg":"MaxRequests \u003c1 or not specified; defaulting to MaxBuffers * 2 == 256","time":"2017-12-15T14:34:04.400941422Z"}
[keep0] {"level":"info","msg":"Trash/delete features are enabled. WARNING: this has not been extensively tested. You should disable this unless you can afford to lose data.","time":"2017-12-15T14:34:04.400989534Z"}
[keep0] {"level":"info","msg":"Using volume [UnixVolume /tmp/tmpe_IOjl] (writable=true)","time":"2017-12-15T14:34:04.401014209Z"}
[keep0] {"level":"info","msg":"keepstore starting, pid 1949","time":"2017-12-15T14:34:04.404598568Z"}
[keep0] {"level":"info","msg":"mount \"/\" device \"overlay\" is not a path; using blank DeviceID for volume [UnixVolume /tmp/tmpe_IOjl]","time":"2017-12-15T14:34:04.406376664Z"}
[keep0] {"level":"info","msg":"listening at [::]:51335","time":"2017-12-15T14:34:04.407221505Z"}
[keep1] time="2017-12-15T14:34:04Z" level=info msg="keepstore dev started"
[keep1] {"level":"info","msg":"MaxRequests \u003c1 or not specified; defaulting to MaxBuffers * 2 == 256","time":"2017-12-15T14:34:04.619341190Z"}
[keep1] {"level":"info","msg":"Trash/delete features are enabled. WARNING: this has not been extensively tested. You should disable this unless you can afford to lose data.","time":"2017-12-15T14:34:04.619414027Z"}
[keep1] {"level":"info","msg":"Using volume [UnixVolume /tmp/tmpA6uj8c] (writable=true)","time":"2017-12-15T14:34:04.619459772Z"}
[keep1] {"level":"info","msg":"keepstore starting, pid 1960","time":"2017-12-15T14:34:04.625660322Z"}
[keep1] {"level":"info","msg":"mount \"/\" device \"overlay\" is not a path; using blank DeviceID for volume [UnixVolume /tmp/tmpA6uj8c]","time":"2017-12-15T14:34:04.627217780Z"}
[keep1] {"level":"info","msg":"listening at [::]:49295","time":"2017-12-15T14:34:04.628094833Z"}
Sent SIGTERM to 1949 (/usr/src/arvados/tmp/keep0.pid)
[keep0] {"level":"info","msg":"caught signal: terminated","time":"2017-12-15T14:34:04.982155866Z"}
[keep0] {"level":"info","msg":"keepstore exiting, pid 1949","time":"2017-12-15T14:34:04.982230278Z"}
Sent SIGTERM to 1960 (/usr/src/arvados/tmp/keep1.pid)
[keep1] {"level":"info","msg":"caught signal: terminated","time":"2017-12-15T14:34:05.082551298Z"}
[keep1] {"level":"info","msg":"keepstore exiting, pid 1960","time":"2017-12-15T14:34:05.082631533Z"}
{"level":"info","msg":"DEPRECATED: No config file found, but ARVADOS_API_HOST and ARVADOS_API_TOKEN environment variables are set. Please use a config file instead.","time":"2017-12-15T14:34:05.208532321Z"}
{"level":"info","msg":"Current configuration:\nClient:\n APIHost: 0.0.0.0:56621\n AuthToken: 4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h\n Insecure: true\nDebug: false\nDefaultReplicas: 0\nDisableGet: false\nDisablePut: false\nListen: :0\nManagementToken: \"\"\nPIDFile: \"\"\nTimeout: 15s\n","time":"2017-12-15T14:34:05.208794940Z"}
{"level":"info","msg":"keepproxy dev started","time":"2017-12-15T14:34:05.208828609Z"}
{"level":"info","msg":"Listening at [::]:46315","time":"2017-12-15T14:34:05.482198469Z"}
----------------------------------------------------------------------
FAIL: keepproxy_test.go:609: NoKeepServerSuite.TestAskGetNoKeepServerError
keepproxy_test.go:628:
c.Check(err, ErrorMatches, `.*HTTP 502.*`)
... error string = "HEAD acbd18db4cc2f85cedef654fccc4a4d8 failed: [http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: Head http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:46315: connect: cannot assign requested address http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: Head http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:46315: connect: cannot assign requested address http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: Head http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:46315: connect: cannot assign requested address]"
... regex string = ".*HTTP 502.*"
keepproxy_test.go:628:
c.Check(err, ErrorMatches, `.*HTTP 502.*`)
... error string = "GET acbd18db4cc2f85cedef654fccc4a4d8 failed: [http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: Get http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:46315: connect: cannot assign requested address http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: Get http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:46315: connect: cannot assign requested address http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: Get http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:46315: connect: cannot assign requested address]"
... regex string = ".*HTTP 502.*"
{"level":"info","msg":"shutting down","time":"2017-12-15T14:34:05.512790603Z"}
OOPS: 6 passed, 8 FAILED, 4 PANICKED
--- FAIL: Test (7.63s)
Updated by Tom Clegg over 6 years ago
Strange. Tests pass here, and on Jenkins (https://ci.curoverse.com/job/developer-run-tests/540/ ... with a node manager integration test fail, presumably just the usual races)
"GET acbd18db4cc2f85cedef654fccc4a4d8 failed: [http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: Get http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:46315: connect: cannot assign requested address http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: Get http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:46315: connect: cannot assign requested address http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: Get http://[::]:46315/acbd18db4cc2f85cedef654fccc4a4d8: dial tcp [::]:46315: connect: cannot assign requested address]"
This seems more likely to be caused by run-tests.sh changes in #8311. Do tests pass for you on master?
Updated by Tom Clegg over 6 years ago
- Status changed from In Progress to Resolved
Actions