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 almost 7 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 almost 7 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 almost 7 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 almost 7 years ago
- Status changed from In Progress to Resolved
Actions