Feature #17014

Add Container Requests endpoint to controller

Added by Nico César 12 months ago. Updated 5 months ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Category:
API
Target version:
-
Start date:
11/10/2020
Due date:
% Done:

100%

Estimated time:
(Total: 0.00 h)
Story points:
-
Release relationship:
Auto

Description

In an effort to embrace container requests in controller and federation, we need to be able to have the endopoint arvados/v1/container_requests in controller.

as part of #16462 we encounter a problem with federation tests in f6ccc08c3f6b1ad42f2c827b19df0300f2c3c3db

We dedided to split out the task of doing first the container request endpoints and later doing the forcasting features (#16462 et al)


Subtasks

Task #17036: Review 17014-controller-container-requests-take2ResolvedNico César


Related issues

Related to Arvados - Bug #17053: Integration test failing Closed

Related to Arvados Epics - Story #9053: Port API server to GoNew06/01/202212/31/2022

Blocks Arvados - Feature #16462: Expand arvados-controller to expose forecast featuresNew

Associated revisions

Revision 70242f2d (diff)
Added by Nico Cesar 12 months ago

Initial commit with tests that are failing

this is the verbose log of failing test:

What next? test lib/controller/federation ======= test lib/controller/federation
ok git.arvados.org/arvados.git/lib/controller/federation 1.178s coverage: 48.1% of statements ======= test lib/controller/federation -- 3s
Pass: lib/controller/federation tests (3s)
All test suites passed.
What next? test lib/controller ======= test lib/controller

----------------------------------------------------------------------
FAIL: federation_test.go:590: FederationSuite.TestCreateContainerRequestBadToken

time="2020-10-16T17:27:40.958155049Z" level=info msg=request RequestID=req-33wrdjmne2bs1nwkc9z8 remoteAddr="192.0.2.1:1234" reqBytes=24 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zzzzz"
time="2020-10-16T17:27:40.958812397Z" level=info msg=response RequestID=req-33wrdjmne2bs1nwkc9z8 remoteAddr="192.0.2.1:1234" reqBytes=24 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zzzzz" respBody="{\"errors\":[\"badly formatted token\"]}\n" respBytes=37 respStatus="Internal Server Error" respStatusCode=500 timeToStatus=0.000649 timeTotal=0.000655 timeWriteBody=0.000006
federation_test.go:599:
c.Check(resp.StatusCode, check.Equals, http.StatusForbidden)
... obtained int = 500
... expected int = 403

federation_test.go:602:
c.Check(e["errors"], check.DeepEquals, []string{"invalid API token"})
... obtained []string = []string{"badly formatted token"}
... expected []string = []string{"invalid API token"}

----------------------------------------------------------------------
FAIL: federation_test.go:630: FederationSuite.TestCreateRemoteContainerRequestCheckRuntimeToken

time="2020-10-16T17:27:41.013982673Z" level=info msg=request RequestID=req-1cdwy5iwe0qw3jgxdjf0 remoteAddr="192.0.2.1:1234" reqBytes=165 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zmock"
time="2020-10-16T17:27:41.015464942Z" level=info msg=response RequestID=req-1cdwy5iwe0qw3jgxdjf0 remoteAddr="192.0.2.1:1234" reqBytes=165 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zmock" respBytes=726 respStatus=OK respStatusCode=200 timeToStatus=0.001473 timeTotal=0.001477 timeWriteBody=0.000004
federation_test.go:659:
c.Check(json.NewDecoder(s.remoteMockRequests0.Body).Decode(&cr), check.IsNil)
... value *json.SyntaxError = &json.SyntaxError{msg:"invalid character 'c' looking for beginning of value", Offset:1} ("invalid character 'c' looking for beginning of value")

federation_test.go:660:
c.Check(strings.HasPrefix(cr.ContainerRequest.RuntimeToken, "v2/zzzzz-gj3su-"), check.Equals, true)
... obtained bool = false
... expected bool = true

----------------------------------------------------------------------
FAIL: federation_test.go:664: FederationSuite.TestCreateRemoteContainerRequestCheckSetRuntimeToken

time="2020-10-16T17:27:41.020613425Z" level=info msg=request RequestID=req-12j635qfrmsbx1jludwq remoteAddr="192.0.2.1:1234" reqBytes=193 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zmock"
time="2020-10-16T17:27:41.022068784Z" level=info msg=response RequestID=req-12j635qfrmsbx1jludwq remoteAddr="192.0.2.1:1234" reqBytes=193 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zmock" respBytes=726 respStatus=OK respStatusCode=200 timeToStatus=0.001450 timeTotal=0.001453 timeWriteBody=0.000003
federation_test.go:690:
c.Check(json.NewDecoder(s.remoteMockRequests0.Body).Decode(&cr), check.IsNil)
... value *json.SyntaxError = &json.SyntaxError{msg:"invalid character 'c' looking for beginning of value", Offset:1} ("invalid character 'c' looking for beginning of value")

federation_test.go:691:
c.Check(cr.ContainerRequest.RuntimeToken, check.Equals, "xyz")
... obtained string = ""
... expected string = "xyz"

----------------------------------------------------------------------
FAIL: federation_test.go:694: FederationSuite.TestCreateRemoteContainerRequestRuntimeTokenFromAuth

time="2020-10-16T17:27:41.030750822Z" level=info msg=request RequestID=req-m6xowfzgvbv2zi2sg8jo remoteAddr="192.0.2.1:1234" reqBytes=165 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zmock"
time="2020-10-16T17:27:41.031717846Z" level=info msg=response RequestID=req-m6xowfzgvbv2zi2sg8jo remoteAddr="192.0.2.1:1234" reqBytes=165 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zmock" respBytes=726 respStatus=OK respStatusCode=200 timeToStatus=0.000961 timeTotal=0.000963 timeWriteBody=0.000002
federation_test.go:719:
c.Check(json.NewDecoder(s.remoteMockRequests0.Body).Decode(&cr), check.IsNil)
... value *json.SyntaxError = &json.SyntaxError{msg:"invalid character 'c' looking for beginning of value", Offset:1} ("invalid character 'c' looking for beginning of value")

federation_test.go:720:
c.Check(cr.ContainerRequest.RuntimeToken, check.Equals, arvadostest.ActiveTokenV2)
... obtained string = ""
... expected string = "v2/zzzzz-gj3su-077z32aux8dg2s1/3kg6k6lzmp9kj5cpkcoxie963cmvjahbt2fod9zru30k1jqdmi"

----------------------------------------------------------------------
FAIL: handler_test.go:321: HandlerSuite.TestGetObjects

handler_test.go:351:
s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:316:
c.Errorf("%s's key %q missing on controller's response.", direct["kind"], k)
... Error: arvados#containerRequest's key "expires_at" missing on controller's response.

handler_test.go:351:
s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:312:
c.Check(val, check.DeepEquals, direct[k],
check.Commentf("RailsAPI %s key %q's value %q differs from controller's %q.", direct["kind"], k, direct[k], val))
... obtained string = ""
... expected = nil
... RailsAPI arvados#containerRequest key "log_uuid"'s value %!q(<nil>) differs from controller's "".

handler_test.go:351:
s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:312:
c.Check(val, check.DeepEquals, direct[k],
check.Commentf("RailsAPI %s key %q's value %q differs from controller's %q.", direct["kind"], k, direct[k], val))
... obtained string = ""
... expected = nil
... RailsAPI arvados#containerRequest key "output_uuid"'s value %!q(<nil>) differs from controller's "".

handler_test.go:351:
s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:316:
c.Errorf("%s's key %q missing on controller's response.", direct["kind"], k)
... Error: arvados#containerRequest's key "container_count" missing on controller's response.

handler_test.go:351:
s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:312:
c.Check(val, check.DeepEquals, direct[k],
check.Commentf("RailsAPI %s key %q's value %q differs from controller's %q.", direct["kind"], k, direct[k], val))
... obtained float64 = 0
... expected = nil
... RailsAPI arvados#containerRequest key "container_count_max"'s value %!q(<nil>) differs from controller's %!q(float64=0).

handler_test.go:351:
s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:316:
c.Errorf("%s's key %q missing on controller's response.", direct["kind"], k)
... Error: arvados#containerRequest's key "filters" missing on controller's response.

handler_test.go:351:
s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:312:
c.Check(val, check.DeepEquals, direct[k],
check.Commentf("RailsAPI %s key %q's value %q differs from controller's %q.", direct["kind"], k, direct[k], val))
... obtained string = ""
... expected = nil
... RailsAPI arvados#containerRequest key "output_name"'s value %!q(<nil>) differs from controller's "".

handler_test.go:351:
s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:312:
c.Check(val, check.DeepEquals, direct[k],
check.Commentf("RailsAPI s key %q's value %q differs from controller's %q.", direct["kind"], k, direct[k], val))
... obtained map[string]interface {} = map[string]interface {}{"API":interface {}(nil), "keep_cache_ram":0, "ram":123, "vcpus":1}
... expected map[string]interface {} = map[string]interface {}{"ram":123, "vcpus":1}
... RailsAPI arvados#containerRequest key "runtime_constraints"'s value map["ram":
!q(float64=123) "vcpus":%!q(float64=1)] differs from controller's map["API":<nil> "keep_cache_ram":%!q(float64=0) "ram":%!q(float64=123) "vcpus":%!q(float64=1)].

handler_test.go:351:
s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:312:
c.Check(val, check.DeepEquals, direct[k],
check.Commentf("RailsAPI s key %q's value %q differs from controller's %q.", direct["kind"], k, direct[k], val))
... obtained map[string]interface {} = map[string]interface {}{"max_run_time":0, "partitions":interface {}(nil), "preemptible":false}
... expected map[string]interface {} = map[string]interface {}{}
... RailsAPI arvados#containerRequest key "scheduling_parameters"'s value map[] differs from controller's map["max_run_time":
!q(float64=0) "partitions":<nil> "preemptible":%!q(bool=false)].

handler_test.go:351:
s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:312:
c.Check(val, check.DeepEquals, direct[k],
check.Commentf("RailsAPI %s key %q's value %q differs from controller's %q.", direct["kind"], k, direct[k], val))
... obtained string = ""
... expected = nil
... RailsAPI arvados#containerRequest key "description"'s value %!q(<nil>) differs from controller's "".

handler_test.go:351:
s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:312:
c.Check(val, check.DeepEquals, direct[k],
check.Commentf("RailsAPI %s key %q's value %q differs from controller's %q.", direct["kind"], k, direct[k], val))
... obtained string = ""
... expected = nil
... RailsAPI arvados#containerRequest key "requesting_container_uuid"'s value %!q(<nil>) differs from controller's "".

----------------------------------------------------------------------
FAIL: integration_test.go:43: IntegrationSuite.SetUpSuite

refs #17014

Arvados-DCO-1.1-Signed-off-by: Nico Cesar <>

Revision 3764a1e0 (diff)
Added by Nico Cesar 10 months ago

17014: controller has container requests

This commit has: * Container Requests in the new codepath * Minimal changes in RailsAPI * Adapted Login and Logout so they work for CR * Tests in lib/controller/integration_test.go that take in account
runtime_token with intermediate clusters * Some tests in lib/controller/federation_test.go had to be addapted,
but for the most part remained as is to gurantee compatibilty * Added the check that SystemRootToken has to be non-empty * RoR fixtures that include finalized CR that are used in the tests to
make sure we return the right object * Minimal changes in the documentation to reflect all the user visible
changes

refs #17014

Arvados-DCO-1.1-Signed-off-by: Nico Cesar <>

Revision c0916b95 (diff)
Added by Nico Cesar 10 months ago

Added /a/v1/<cr_uuid>/datapoints endpoint to controller

This builds on top of the work we've done in 17014 this is
the inclusion of the forecast datapoints and the relevant tests

refs #16462
refs #17014

Arvados-DCO-1.1-Signed-off-by: Nico Cesar <>

Revision 87237527 (diff)
Added by Nico Cesar 9 months ago

17014: controller handles container requests

This commit has: * Container Requests in the new codepath * runtime_constraints and scheduling parameters have now default
values and cannot be nil. This affects Railsapi CR comparison
in Final state * Adapted Login and Logout so they work for CR * Tests in lib/controller/integration_test.go that take in account
runtime_token with intermediate clusters * Some tests in lib/controller/federation_test.go had to be addapted,
but for the most part remained as is to gurantee compatibilty * Added the check that SystemRootToken has to be non-empty * Railsapi fixtures that include finalized CR that are used in the tests to
make sure we return the right object * Minimal changes in the documentation to reflect all the user visible
changes

refs #17014

Arvados-DCO-1.1-Signed-off-by: Nico Cesar <>

Revision 4c6c4919
Added by Nico Cesar 9 months ago

Merge branch '17014-controller-container-requests-take3'

closes #17014

Arvados-DCO-1.1-Signed-off-by: Nico Cesar <>

History

#1 Updated by Peter Amstutz 12 months ago

  • Status changed from New to In Progress

#2 Updated by Peter Amstutz 12 months ago

  • Target version changed from 2020-10-21 Sprint to 2020-11-04 Sprint

#3 Updated by Nico César 12 months ago

  • Blocks Feature #16462: Expand arvados-controller to expose forecast features added

#4 Updated by Nico César 12 months ago

  • Related to Bug #17053: Integration test failing added

#5 Updated by Nico César 12 months ago

  • Target version changed from 2020-11-04 Sprint to 2020-11-18

#6 Updated by Nico César 11 months ago

branch 17014-controller-container-requests has commit 9e312753855286a7e21c83218bb48589f4d1535d as soon as https://ci.arvados.org/job/developer-run-tests/2172/ is done is ready for review

#7 Updated by Nico César 11 months ago

#8 Updated by Tom Clegg 11 months ago

In lib/controller/cmd.go, "Command intantiates(sic) a cmd.Handler with the service.Command used in package cmd" ... this might help lint, but I'm not sure it helps a human. How about: "Command starts a controller service."

In lib/controller/federation.go / validateAPItoken(), what's the significance of the "len(token) < 41" case? It seems like validateToken won't validate a salted token any more, or a bare token (e.g. OIDC access token) that happens to be 40 chars or less, but I'm not following why that change is desirable. (Also, typo "lenght" in debug message)

In sdk/go/arvados/container.go:
  • Filters should be []Filter rather than []string
  • ContainerUUID should be a string rather than *string ("" and null do not have different meanings) -- note we might need to fix some client code, if any clients rely on the current undocumented behavior where container_uuid is null rather than empty
  • ExpiresAt should be a time.Time rather than a string
In lib/controller/router/response.go:
  • The comment "by default they will have been encoded to..." (my bad?) should say "otherwise they would use the default time encoding, ..."
  • The HasSuffix(k, "_at") block should have a "continue" at the end, and "expires_at" isn't needed in the switch statement below
  • If we were already returning empty (non-nil) modified_by_client_uuid fields with no ill effects, we should keep doing so instead of making them null
  • Likewise I don't think we need to munge the description field, either, it's okay to return ""
  • We don't document whether "requesting_container_uuid" is null or empty, and python/javascript clients probably won't care either way, so I'm inclined to return "" and just make sure things still work well if a client copies the response into an update request and updates it to "" -- i.e., make sure Rails accepts "" to mean "none" in an update/create.
  • That leaves "output_uuid", and "log_uuid" which are documented to be null when not applicable, so I guess we do need to munge those
  • Looking at the relevant RailsAPI code for container request update/create calls, it seems like setting output_name="" causes the resulting collection name to be nil, while setting output_name=nil causes the collection name to be "Container #{out_type} for request #{uuid}". I think this is probably an accident and we should fix this in services/api/app/models/container_request.rb:197 so a nil output_name gets converted to "" on the way in, and "" invokes the automatic naming. Then we can update the docs to say "If null or empty". https://doc.arvados.org/v1.2/api/methods/container_requests.html
  • I think the comment "RoR returns nil instead of the Zero value" is misleading. The requirement is to make the response fit the client's expectations, which won't change when we stop using RoR (even though we can blame RoR for creating that expectation in the first place).
In lib/controller/localdb/conn.go
  • copypaste error in "Login handles the logout ..."
  • typo "appropiate" in all three comments
Regarding deleted tests:
  • I don't think the new tests have enough coverage to make up for the deleted tests, which
    • use federation features to submit CRs via intermediate clusters
    • submit CRs as a non-root user
  • Why delete them / can we make them pass?

Tests:

TestDatabaseConnection: Rather than making a separate test that tests a copy of the database-connecting code used by other tests, how about making a private "get database handle" method that tries "select 1" to try it before returning, something like

func (s *IntegrationSuite) dbConn(c *check.C, clusterID string) (*sql.DB, *sql.Conn) {
  db, err := sql.Open(...)
  c.Assert(err,check.IsNil)
  // ...
  n, err := conn.Exec(`SELECT 1`)
  c.Assert(n, check.Equals, int64(1))
  return db, conn
}

Then TestRuntimeTokenInCR can do something like

  db, conn := s.dbConn(c, "z1111")
  defer conn.Close()
  defer db.Close()
  row := conn.QueryRow(`SELECT ...`)
  var token sql.NullString
  row.Scan(&token)
  if c.Check(token.Valid, check.Equals, true) {
    c.Check(token.String, check.Equals, tt.expectedToken
  }

(sql.NullString is a bit less awkward than a *string)

I expect you meant "continue" (next trial) rather than "break" (don't run any more trials) here in TestRuntimeTokenInCR:

               if tt.expectedToken == nil {
                       break
               }

When you're not actually using the cancel func returned by context.WithCancel(), don't use that -- just pass context.Background() to funcs that need a context (or use the non-context variant if applicable, like conn.QueryRow).

Use c.Check instead of c.Assert when it's still possible to do more checks, especially in a parameterized test -- otherwise the whole test func stops and you never find out (for example) whether a single test loop failed, or all of them. You can give up on a single iteration of the "tt" loop in the TestRuntimeTokenInCR test like this:

if !c.Check(row, check.NotNil) {
        continue
}

Although in this case it doesn't look like a problem, I'd still suggest avoiding pointers like expectedToken in test cases: in general, if the code being tested unexpectedly changes ac1.AuthToken, *expected will also change, and checking "*expected == *actual" doesn't necessarily test what you think it does. (In this particular case expectedToken doesn't even need to be a pointer.)

Comparing strings (runtimeToken / expectedToken) doesn't need DeepEquals, just Equals.

#9 Updated by Nico César 11 months ago

I commited 7670ec444f87d59b1c9151b2509cfd8e8facbd2c test: https://ci.arvados.org/view/Developer/job/developer-run-tests/2176/

I partially did some of the comments.

Tom Clegg wrote:

In lib/controller/federation.go / validateAPItoken(), what's the significance of the "len(token) < 41" case? It seems like validateToken won't validate a salted token any more, or a bare token (e.g. OIDC access token) that happens to be 40 chars or less, but I'm not following why that change is desirable. (Also, typo "lenght" in debug message)

This was change that started as a "len(token) == 0", then realized that some queries had tokens like "abcdef". In this commit I removed this completly, will fix other places as need

In sdk/go/arvados/container.go:
  • Filters should be []Filter rather than []string

Done.

  • ContainerUUID should be a string rather than *string ("" and null do not have different meanings) -- note we might need to fix some client code, if any clients rely on the current undocumented behavior where container_uuid is null rather than empty

I'm leaving this change for last, but yes, I agree this should be a string (and "" when there is no container yet for that container request)

  • ExpiresAt should be a time.Time rather than a string

Done.

In lib/controller/router/response.go:
  • The comment "by default they will have been encoded to..." (my bad?) should say "otherwise they would use the default time encoding, ..."

Changed some comments

  • The HasSuffix(k, "_at") block should have a "continue" at the end, and "expires_at" isn't needed in the switch statement below

This is odd... please look at 7670ec444f87d59b1c9151b2509cfd8e8facbd2c, for some reason the "case time.Time" is not covering that case. Am I missing a continue somewhere I can't see?

  • If we were already returning empty (non-nil) modified_by_client_uuid fields with no ill effects, we should keep doing so instead of making them null
  • Likewise I don't think we need to munge the description field, either, it's okay to return ""
  • We don't document whether "requesting_container_uuid" is null or empty, and python/javascript clients probably won't care either way, so I'm inclined to return "" and just make sure things still work well if a client copies the response into an update request and updates it to "" -- i.e., make sure Rails accepts "" to mean "none" in an update/create.
  • That leaves "output_uuid", and "log_uuid" which are documented to be null when not applicable, so I guess we do need to munge those
  • I think the comment "RoR returns nil instead of the Zero value" is misleading. The requirement is to make the response fit the client's expectations, which won't change when we stop using RoR (even though we can blame RoR for creating that expectation in the first place).

I bundle all this in one comment. Basically lib/controller/handler_test.go:TestGetObjects should be getting the same objects for RoR and for our CR in new codepath controller.... I know we can get better, but that would mean to change this particular test. I'm worried that change will end up biting us... I prefer to have a lot of explicit code that mimics still-in-use-legacy and a good comment to make whatever we need to make when sunsetting rails. I don't even mind starting a comment with SUNSETTING_RAILS_API:.... with explicit instructions what to do when that happens.

Does this makes sense to you?

  • Looking at the relevant RailsAPI code for container request update/create calls, it seems like setting output_name="" causes the resulting collection name to be nil, while setting output_name=nil causes the collection name to be "Container #{out_type} for request #{uuid}". I think this is probably an accident and we should fix this in services/api/app/models/container_request.rb:197 so a nil output_name gets converted to "" on the way in, and "" invokes the automatic naming. Then we can update the docs to say "If null or empty". https://doc.arvados.org/v1.2/api/methods/container_requests.html

ok. noted... I'll add this to changes I'll do in later commits, I think some tests will have to be reviewed with this change

In lib/controller/localdb/conn.go
  • copypaste error in "Login handles the logout ..."
  • typo "appropiate" in all three comments

done

Regarding deleted tests:
  • I don't think the new tests have enough coverage to make up for the deleted tests, which
    • use federation features to submit CRs via intermediate clusters
    • submit CRs as a non-root user
  • Why delete them / can we make them pass?

1) I agree 1.1) and 1.2) I'll add this to the new tests

2) Regardless what happens about 1)... one of the reasons I took out the old tests is because error reporting for 403's are different. I'll take a 2nd pass to see if I can bring them back.

Tests:

TestDatabaseConnection ... how about making a private "get database handle"

I'll do this tomorrow, looks like an easy change

When you're not actually using the cancel func returned by context.WithCancel(), don't use that -- just pass context.Background() to funcs that need a context (or use the non-context variant if applicable, like conn.QueryRow).

Noted.

Use c.Check instead of c.Assert when it's still possible to do more checks, especially in a parameterized test -- otherwise the whole test func stops and you never find out (for example) whether a single test loop failed, or all of them. You can give up on a single iteration of the "tt" loop in the TestRuntimeTokenInCR test like this:

Same as continue vs break: I was trying to get my dev cycle faster... but I see the case where this is executed in ci.arvados.org and is better to have "all errors" rather than the first one found. I'll change that and see how to use -failfast for my cycle.

Although in this case it doesn't look like a problem, I'd still suggest avoiding pointers like expectedToken in test cases: in general, if the code being tested unexpectedly changes ac1.AuthToken, *expected will also change, and checking "*expected == *actual" doesn't necessarily test what you think it does. (In this particular case expectedToken doesn't even need to be a pointer.)

Comparing strings (runtimeToken / expectedToken) doesn't need DeepEquals, just Equals.

#10 Updated by Nico César 11 months ago

I started arvbox with workflows:

rails db:fixtures:load FIXTURES=workflows

Then I get the following: (notice the empty sting in )

==> /etc/service/api/log/main/current <==
2020-11-17_23:36:08.66530    (0.2ms)  SET TIME ZONE 'UTC'
2020-11-17_23:36:08.66627   ApiClientAuthorization Load (0.4ms)  SELECT  "api_client_authorizations".* FROM "api_client_authorizations" WHERE (uuid='xsjpe-gj3su-24tscjwoyuv42kb' and (expires_at is null or expires_at > CURRENT_TIMESTAMP)) ORDER BY "api_client_authorizations"."id" ASC LIMIT $1  [["LIMIT", 1]]
2020-11-17_23:36:08.66763   User Load (0.3ms)  SELECT "users".* FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."id" = $1  [["id", 3]]
2020-11-17_23:36:08.66882   ApiClient Load (0.2ms)  SELECT "api_clients".* FROM "api_clients" WHERE "api_clients"."id" = $1  [["id", 4]]
2020-11-17_23:36:08.67231 [req-4n7zt2yuoh2i252o0ygn]   Link Load (0.2ms)  SELECT "links".* FROM "links" WHERE "links"."head_uuid" = $1 AND "links"."link_class" = $2  [["head_uuid", "xsjpe-tpzed-jd0k6trjpsytxw6"], ["link_class", "permission"]]
2020-11-17_23:36:08.67334 {"method":"GET","path":"/arvados/v1/users/current","format":"html","controller":"Arvados::V1::UsersController","action":"current","status":200,"duration":2.47,"view":0.23,"db":0.22,"request_id":"req-4n7zt2yuoh2i252o0ygn","client_ipaddr":"127.0.0.1","client_auth":"xsjpe-gj3su-24tscjwoyuv42kb","params":{},"@timestamp":"2020-11-17T23:36:08.673237873Z","@version":"1","message":"[200] GET /arvados/v1/users/current (Arvados::V1::UsersController#current)"}
2020-11-17_23:36:08.68271    (0.2ms)  SET TIME ZONE 'UTC'
2020-11-17_23:36:08.68360   ApiClientAuthorization Load (0.3ms)  SELECT  "api_client_authorizations".* FROM "api_client_authorizations" WHERE (uuid='xsjpe-gj3su-24tscjwoyuv42kb' and (expires_at is null or expires_at > CURRENT_TIMESTAMP)) ORDER BY "api_client_authorizations"."id" ASC LIMIT $1  [["LIMIT", 1]]
2020-11-17_23:36:08.68495   User Load (0.3ms)  SELECT "users".* FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."id" = $1  [["id", 3]]
2020-11-17_23:36:08.68597   ApiClient Load (0.1ms)  SELECT "api_clients".* FROM "api_clients" WHERE "api_clients"."id" = $1  [["id", 4]]
2020-11-17_23:36:08.68902 [req-4n7zt2yuoh2i252o0ygn]    (0.1ms)  BEGIN
2020-11-17_23:36:08.68964 [req-4n7zt2yuoh2i252o0ygn]   ContainerRequest Load (0.3ms)  SELECT  (octet_length(container_requests.mounts)) as read_length FROM "container_requests" WHERE (container_requests.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) ) AND ((container_requests.requesting_container_uuid is null)) ORDER BY container_requests.created_at desc, container_requests.modified_at desc, container_requests.uuid LIMIT $1 OFFSET $2  [["LIMIT", 12], ["OFFSET", 0]]
2020-11-17_23:36:08.69130 [req-4n7zt2yuoh2i252o0ygn]   ContainerRequest Load (0.4ms)  SELECT  "container_requests".* FROM "container_requests" WHERE (container_requests.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) ) AND ((container_requests.requesting_container_uuid is null)) ORDER BY container_requests.created_at desc, container_requests.modified_at desc, container_requests.uuid LIMIT $1 OFFSET $2  [["LIMIT", 12], ["OFFSET", 0]]
2020-11-17_23:36:08.69653 [req-4n7zt2yuoh2i252o0ygn]    (0.1ms)  COMMIT
2020-11-17_23:36:08.69924 {"method":"GET","path":"/arvados/v1/container_requests","format":"html","controller":"Arvados::V1::ContainerRequestsController","action":"index","status":200,"duration":11.37,"view":0.19,"db":0.9,"request_id":"req-4n7zt2yuoh2i252o0ygn","client_ipaddr":"127.0.0.1","client_auth":"xsjpe-gj3su-24tscjwoyuv42kb","params":{"cluster_id":"","count":"none","filters":"[[\"requesting_container_uuid\",\"=\",null]]","forwarded_for":"xsjpe-","limit":"12","offset":"0","order":"[\"created_at desc\"]"},"@timestamp":"2020-11-17T23:36:08.699139816Z","@version":"1","message":"[200] GET /arvados/v1/container_requests (Arvados::V1::ContainerRequestsController#index)"}
2020-11-17_23:36:08.71411    (0.2ms)  SET TIME ZONE 'UTC'
2020-11-17_23:36:08.71484   ApiClientAuthorization Load (0.3ms)  SELECT  "api_client_authorizations".* FROM "api_client_authorizations" WHERE (uuid='xsjpe-gj3su-24tscjwoyuv42kb' and (expires_at is null or expires_at > CURRENT_TIMESTAMP)) ORDER BY "api_client_authorizations"."id" ASC LIMIT $1  [["LIMIT", 1]]
2020-11-17_23:36:08.71617   User Load (0.3ms)  SELECT "users".* FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."id" = $1  [["id", 3]]
2020-11-17_23:36:08.71720   ApiClient Load (0.1ms)  SELECT "api_clients".* FROM "api_clients" WHERE "api_clients"."id" = $1  [["id", 4]]
2020-11-17_23:36:08.72032 [req-4n7zt2yuoh2i252o0ygn]    (0.1ms)  BEGIN
2020-11-17_23:36:08.72094 [req-4n7zt2yuoh2i252o0ygn]   ContainerRequest Load (0.4ms)  SELECT  (octet_length(container_requests.mounts)) as read_length FROM "container_requests" WHERE (container_requests.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) ) AND ((container_requests.requesting_container_uuid is null)) ORDER BY container_requests.created_at desc, container_requests.modified_at desc, container_requests.uuid LIMIT $1 OFFSET $2  [["LIMIT", 6], ["OFFSET", 6]]
2020-11-17_23:36:08.72152 [req-4n7zt2yuoh2i252o0ygn]   ContainerRequest Load (0.3ms)  SELECT  "container_requests".* FROM "container_requests" WHERE (container_requests.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) ) AND ((container_requests.requesting_container_uuid is null)) ORDER BY container_requests.created_at desc, container_requests.modified_at desc, container_requests.uuid LIMIT $1 OFFSET $2  [["LIMIT", 6], ["OFFSET", 6]]
2020-11-17_23:36:08.72185 [req-4n7zt2yuoh2i252o0ygn]    (0.1ms)  COMMIT
2020-11-17_23:36:08.72231 {"method":"GET","path":"/arvados/v1/container_requests","format":"html","controller":"Arvados::V1::ContainerRequestsController","action":"index","status":200,"duration":3.14,"view":0.19,"db":0.87,"request_id":"req-4n7zt2yuoh2i252o0ygn","client_ipaddr":"127.0.0.1","client_auth":"xsjpe-gj3su-24tscjwoyuv42kb","params":{"cluster_id":"","count":"none","filters":"[[\"requesting_container_uuid\",\"=\",null]]","forwarded_for":"xsjpe-","limit":"6","offset":"6","order":"[\"created_at desc\"]"},"@timestamp":"2020-11-17T23:36:08.722190568Z","@version":"1","message":"[200] GET /arvados/v1/container_requests (Arvados::V1::ContainerRequestsController#index)"}
2020-11-17_23:36:08.72522    (0.1ms)  SET TIME ZONE 'UTC'
2020-11-17_23:36:08.72593   ApiClientAuthorization Load (0.3ms)  SELECT  "api_client_authorizations".* FROM "api_client_authorizations" WHERE (uuid='xsjpe-gj3su-24tscjwoyuv42kb' and (expires_at is null or expires_at > CURRENT_TIMESTAMP)) ORDER BY "api_client_authorizations"."id" ASC LIMIT $1  [["LIMIT", 1]]
2020-11-17_23:36:08.72706   User Load (0.2ms)  SELECT "users".* FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."id" = $1  [["id", 3]]
2020-11-17_23:36:08.72797   ApiClient Load (0.1ms)  SELECT "api_clients".* FROM "api_clients" WHERE "api_clients"."id" = $1  [["id", 4]]
2020-11-17_23:36:08.73032 [req-4n7zt2yuoh2i252o0ygn]   ApiClientAuthorization Load (0.2ms)  SELECT "api_client_authorizations".* FROM "api_client_authorizations" WHERE (api_token IN (NULL) AND
2020-11-17_23:36:08.73032                 (expires_at IS NULL OR expires_at > CURRENT_TIMESTAMP))
2020-11-17_23:36:08.73137 [req-4n7zt2yuoh2i252o0ygn]    (0.1ms)  BEGIN
2020-11-17_23:36:08.73199 [req-4n7zt2yuoh2i252o0ygn]   Container Load (0.4ms)  SELECT  (octet_length(containers.mounts)) as read_length FROM "containers" WHERE (containers.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) ) AND (containers.uuid in ('','xsjpe-dz642-fu9pth30j364hm8','xsjpe-dz642-7wwe7g976v6l4ox','xsjpe-dz642-rr5tkzewia50xco','xsjpe-dz642-wkofonabvgm18xn')) ORDER BY containers.modified_at desc, containers.uuid LIMIT $1 OFFSET $2  [["LIMIT", 1000], ["OFFSET", 0]]
2020-11-17_23:36:08.73350 [req-4n7zt2yuoh2i252o0ygn]   Container Load (0.5ms)  SELECT  "containers".* FROM "containers" WHERE (containers.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) ) AND (containers.uuid in ('','xsjpe-dz642-fu9pth30j364hm8','xsjpe-dz642-7wwe7g976v6l4ox','xsjpe-dz642-rr5tkzewia50xco','xsjpe-dz642-wkofonabvgm18xn')) ORDER BY containers.modified_at desc, containers.uuid LIMIT $1 OFFSET $2  [["LIMIT", 1000], ["OFFSET", 0]]
2020-11-17_23:36:08.73745 [req-4n7zt2yuoh2i252o0ygn]    (0.1ms)  COMMIT
2020-11-17_23:36:08.73955 [req-4n7zt2yuoh2i252o0ygn]    (0.3ms)  SELECT COUNT(*) FROM "containers" WHERE (containers.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) ) AND (containers.uuid in ('','xsjpe-dz642-fu9pth30j364hm8','xsjpe-dz642-7wwe7g976v6l4ox','xsjpe-dz642-rr5tkzewia50xco','xsjpe-dz642-wkofonabvgm18xn'))
2020-11-17_23:36:08.74021 {"method":"GET","path":"/arvados/v1/containers","format":"json","controller":"Arvados::V1::ContainersController","action":"index","status":200,"duration":10.39,"view":0.22,"db":1.52,"request_id":"req-4n7zt2yuoh2i252o0ygn","client_ipaddr":"127.0.0.1","client_auth":"xsjpe-gj3su-24tscjwoyuv42kb","params":{"reader_tokens":"[]","_method":"GET","where":"{\"uuid\":[\"\",\"xsjpe-dz642-fu9pth30j364hm8\",\"xsjpe-dz642-7wwe7g976v6l4ox\",\"xsjpe-dz642-rr5tkzewia50xco\",\"xsjpe-dz642-wkofonabvgm18xn\"]}","limit":"9223372036854775807","offset":"0","_profile":"true"},"@timestamp":"2020-11-17T23:36:08.740135948Z","@version":"1","message":"[200] GET /arvados/v1/containers (Arvados::V1::ContainersController#index)"}
2020-11-17_23:36:08.75123    (0.2ms)  SET TIME ZONE 'UTC'
2020-11-17_23:36:08.75200   ApiClientAuthorization Load (0.3ms)  SELECT  "api_client_authorizations".* FROM "api_client_authorizations" WHERE (uuid='xsjpe-gj3su-24tscjwoyuv42kb' and (expires_at is null or expires_at > CURRENT_TIMESTAMP)) ORDER BY "api_client_authorizations"."id" ASC LIMIT $1  [["LIMIT", 1]]
2020-11-17_23:36:08.75310   User Load (0.2ms)  SELECT "users".* FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."id" = $1  [["id", 3]]
2020-11-17_23:36:08.75399   ApiClient Load (0.1ms)  SELECT "api_clients".* FROM "api_clients" WHERE "api_clients"."id" = $1  [["id", 4]]
2020-11-17_23:36:08.75687 [req-4n7zt2yuoh2i252o0ygn]   Link Load (0.1ms)  SELECT "links".* FROM "links" WHERE "links"."head_uuid" = $1 AND "links"."link_class" = $2  [["head_uuid", "xsjpe-tpzed-jd0k6trjpsytxw6"], ["link_class", "permission"]]
2020-11-17_23:36:08.75775 {"method":"GET","path":"/arvados/v1/users/current","format":"html","controller":"Arvados::V1::UsersController","action":"current","status":200,"duration":1.94,"view":0.17,"db":0.14,"request_id":"req-4n7zt2yuoh2i252o0ygn","client_ipaddr":"127.0.0.1","client_auth":"xsjpe-gj3su-24tscjwoyuv42kb","params":{},"@timestamp":"2020-11-17T23:36:08.757625006Z","@version":"1","message":"[200] GET /arvados/v1/users/current (Arvados::V1::UsersController#current)"}
2020-11-17_23:36:08.76142    (0.1ms)  SET TIME ZONE 'UTC'
2020-11-17_23:36:08.76212   ApiClientAuthorization Load (0.3ms)  SELECT  "api_client_authorizations".* FROM "api_client_authorizations" WHERE (uuid='xsjpe-gj3su-24tscjwoyuv42kb' and (expires_at is null or expires_at > CURRENT_TIMESTAMP)) ORDER BY "api_client_authorizations"."id" ASC LIMIT $1  [["LIMIT", 1]]
2020-11-17_23:36:08.76314   User Load (0.2ms)  SELECT "users".* FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."id" = $1  [["id", 3]]
2020-11-17_23:36:08.76403   ApiClient Load (0.1ms)  SELECT "api_clients".* FROM "api_clients" WHERE "api_clients"."id" = $1  [["id", 4]]
2020-11-17_23:36:08.76682 [req-4n7zt2yuoh2i252o0ygn]   ApiClientAuthorization Load (0.3ms)  SELECT "api_client_authorizations".* FROM "api_client_authorizations" WHERE (api_token IN (NULL) AND
2020-11-17_23:36:08.76683                 (expires_at IS NULL OR expires_at > CURRENT_TIMESTAMP))
2020-11-17_23:36:08.76898 [req-4n7zt2yuoh2i252o0ygn]   Link Load (0.4ms)  SELECT  links."head_uuid" FROM "links" WHERE (links.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) ) AND ((links.owner_uuid in ('xsjpe-j7d0g-publicfavorites','xsjpe-tpzed-jd0k6trjpsytxw6')) AND (links.link_class = 'star') AND (substring(links.head_uuid, 7, 5) = 'j7d0g')) LIMIT $1 OFFSET $2  [["LIMIT", 1000], ["OFFSET", 0]]
2020-11-17_23:36:08.76947 {"method":"GET","path":"/arvados/v1/links","format":"json","controller":"Arvados::V1::LinksController","action":"index","status":200,"duration":3.42,"view":0.21,"db":0.74,"request_id":"req-4n7zt2yuoh2i252o0ygn","client_ipaddr":"127.0.0.1","client_auth":"xsjpe-gj3su-24tscjwoyuv42kb","params":{"reader_tokens":"[]","_method":"GET","count":"none","select":"[\"head_uuid\"]","filters":"[[\"owner_uuid\",\"in\",[\"xsjpe-j7d0g-publicfavorites\",\"xsjpe-tpzed-jd0k6trjpsytxw6\"]],[\"link_class\",\"=\",\"star\"],[\"head_uuid\",\"is_a\",\"arvados#group\"]]","limit":"9223372036854775807","offset":"0","_profile":"true"},"@timestamp":"2020-11-17T23:36:08.769394636Z","@version":"1","message":"[200] GET /arvados/v1/links (Arvados::V1::LinksController#index)"}
2020-11-17_23:36:08.77271    (0.2ms)  SET TIME ZONE 'UTC'
2020-11-17_23:36:08.77341   ApiClientAuthorization Load (0.3ms)  SELECT  "api_client_authorizations".* FROM "api_client_authorizations" WHERE (uuid='xsjpe-gj3su-24tscjwoyuv42kb' and (expires_at is null or expires_at > CURRENT_TIMESTAMP)) ORDER BY "api_client_authorizations"."id" ASC LIMIT $1  [["LIMIT", 1]]
2020-11-17_23:36:08.77458   User Load (0.3ms)  SELECT "users".* FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."id" = $1  [["id", 3]]
2020-11-17_23:36:08.77547   ApiClient Load (0.1ms)  SELECT "api_clients".* FROM "api_clients" WHERE "api_clients"."id" = $1  [["id", 4]]
2020-11-17_23:36:08.77761 [req-4n7zt2yuoh2i252o0ygn]   ApiClientAuthorization Load (0.2ms)  SELECT "api_client_authorizations".* FROM "api_client_authorizations" WHERE (api_token IN (NULL) AND
2020-11-17_23:36:08.77761                 (expires_at IS NULL OR expires_at > CURRENT_TIMESTAMP))
2020-11-17_23:36:08.77890 [req-4n7zt2yuoh2i252o0ygn]   Group Load (0.3ms)  SELECT  "groups".* FROM "groups" WHERE (groups.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) AND (groups.trash_at is NULL or groups.trash_at > statement_timestamp())) AND ((groups.uuid in (NULL))) ORDER BY groups.name asc, groups.modified_at desc, groups.uuid LIMIT $1 OFFSET $2  [["LIMIT", 1000], ["OFFSET", 0]]
2020-11-17_23:36:08.77935 {"method":"GET","path":"/arvados/v1/groups","format":"json","controller":"Arvados::V1::GroupsController","action":"index","status":200,"duration":2.18,"view":0.17,"db":0.47,"request_id":"req-4n7zt2yuoh2i252o0ygn","client_ipaddr":"127.0.0.1","client_auth":"xsjpe-gj3su-24tscjwoyuv42kb","params":{"reader_tokens":"[]","_method":"GET","count":"none","order":"name","filters":"[[\"uuid\",\"in\",[]]]","limit":"9223372036854775807","offset":"0","_profile":"true"},"@timestamp":"2020-11-17T23:36:08.779281547Z","@version":"1","message":"[200] GET /arvados/v1/groups (Arvados::V1::GroupsController#index)"}
2020-11-17_23:36:08.78271    (0.2ms)  SET TIME ZONE 'UTC'
2020-11-17_23:36:08.78346   ApiClientAuthorization Load (0.3ms)  SELECT  "api_client_authorizations".* FROM "api_client_authorizations" WHERE (uuid='xsjpe-gj3su-24tscjwoyuv42kb' and (expires_at is null or expires_at > CURRENT_TIMESTAMP)) ORDER BY "api_client_authorizations"."id" ASC LIMIT $1  [["LIMIT", 1]]
2020-11-17_23:36:08.78463   User Load (0.2ms)  SELECT "users".* FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."id" = $1  [["id", 3]]
2020-11-17_23:36:08.78560   ApiClient Load (0.1ms)  SELECT "api_clients".* FROM "api_clients" WHERE "api_clients"."id" = $1  [["id", 4]]
2020-11-17_23:36:08.78783 [req-4n7zt2yuoh2i252o0ygn]   ApiClientAuthorization Load (0.2ms)  SELECT "api_client_authorizations".* FROM "api_client_authorizations" WHERE (api_token IN (NULL) AND
2020-11-17_23:36:08.78784                 (expires_at IS NULL OR expires_at > CURRENT_TIMESTAMP))
2020-11-17_23:36:08.78921 [req-4n7zt2yuoh2i252o0ygn]   Group Load (0.3ms)  SELECT  "groups".* FROM "groups" WHERE (groups.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) AND (groups.trash_at is NULL or groups.trash_at > statement_timestamp())) AND ((groups.group_class = 'project') AND (groups.owner_uuid in ('xsjpe-tpzed-jd0k6trjpsytxw6'))) ORDER BY groups.name asc, groups.modified_at desc, groups.uuid LIMIT $1 OFFSET $2  [["LIMIT", 200], ["OFFSET", 0]]
2020-11-17_23:36:08.78974 [req-4n7zt2yuoh2i252o0ygn]    (0.2ms)  SELECT COUNT(*) FROM "groups" WHERE (groups.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) AND (groups.trash_at is NULL or groups.trash_at > statement_timestamp())) AND ((groups.group_class = 'project') AND (groups.owner_uuid in ('xsjpe-tpzed-jd0k6trjpsytxw6')))
2020-11-17_23:36:08.79021 {"method":"GET","path":"/arvados/v1/groups","format":"json","controller":"Arvados::V1::GroupsController","action":"index","status":200,"duration":2.82,"view":0.22,"db":0.76,"request_id":"req-4n7zt2yuoh2i252o0ygn","client_ipaddr":"127.0.0.1","client_auth":"xsjpe-gj3su-24tscjwoyuv42kb","params":{"reader_tokens":"[]","_method":"GET","order":"name","filters":"[[\"group_class\",\"=\",\"project\"],[\"owner_uuid\",\"in\",[\"xsjpe-tpzed-jd0k6trjpsytxw6\"]]]","limit":"200","offset":"0","_profile":"true"},"@timestamp":"2020-11-17T23:36:08.790138429Z","@version":"1","message":"[200] GET /arvados/v1/groups (Arvados::V1::GroupsController#index)"}
2020-11-17_23:36:08.93163 [req-9plyt6fg30rjmg8yoslm]    (0.3ms)  SET TIME ZONE 'UTC'
2020-11-17_23:36:08.93224 [req-9plyt6fg30rjmg8yoslm]    (0.2ms)  SELECT clock_timestamp() AT TIME ZONE 'UTC'
2020-11-17_23:36:09.13544 {"method":"GET","path":"/discovery/v1/apis/arvados/v1/rest","format":"json","controller":"Arvados::V1::SchemaController","action":"index","status":200,"duration":206.17,"view":0.22,"db":0.56,"request_id":"req-9plyt6fg30rjmg8yoslm","client_ipaddr":"127.0.0.1","client_auth":null,"params":{},"@timestamp":"2020-11-17T23:36:09.135190517Z","@version":"1","message":"[200] GET /discovery/v1/apis/arvados/v1/rest (Arvados::V1::SchemaController#index)"}

==> /etc/service/controller/log/main/current <==
2020-11-17_23:36:08.66410 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"request","remoteAddr":"127.0.0.1:54248","reqBytes":46,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/users/current","reqQuery":"","time":"2020-11-17T23:36:08.664053033Z"}
2020-11-17_23:36:08.67416 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"response","remoteAddr":"127.0.0.1:54248","reqBytes":46,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/users/current","reqQuery":"","respBytes":617,"respStatus":"OK","respStatusCode":200,"time":"2020-11-17T23:36:08.674118722Z","timeToStatus":0.010054,"timeTotal":0.010060,"timeWriteBody":0.000006}
2020-11-17_23:36:08.68141 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"request","remoteAddr":"127.0.0.1:54250","reqBytes":180,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/container_requests","reqQuery":"","time":"2020-11-17T23:36:08.681360117Z"}
2020-11-17_23:36:08.70199 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"response","remoteAddr":"127.0.0.1:54250","reqBytes":180,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/container_requests","reqQuery":"","respBytes":24030,"respStatus":"OK","respStatusCode":200,"time":"2020-11-17T23:36:08.701956146Z","timeToStatus":0.020552,"timeTotal":0.020592,"timeWriteBody":0.000040}
2020-11-17_23:36:08.71294 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"request","remoteAddr":"127.0.0.1:54252","reqBytes":179,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/container_requests","reqQuery":"","time":"2020-11-17T23:36:08.712897727Z"}
2020-11-17_23:36:08.72287 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"response","remoteAddr":"127.0.0.1:54252","reqBytes":179,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/container_requests","reqQuery":"","respBytes":72,"respStatus":"OK","respStatusCode":200,"time":"2020-11-17T23:36:08.722818622Z","timeToStatus":0.009907,"timeTotal":0.009914,"timeWriteBody":0.000007}
2020-11-17_23:36:08.72442 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"request","remoteAddr":"127.0.0.1:54254","reqBytes":263,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/containers","reqQuery":"","time":"2020-11-17T23:36:08.724388054Z"}
2020-11-17_23:36:08.74087 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"response","remoteAddr":"127.0.0.1:54254","reqBytes":263,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/containers","reqQuery":"","respBytes":15267,"respStatus":"OK","respStatusCode":200,"time":"2020-11-17T23:36:08.740794424Z","timeToStatus":0.016227,"timeTotal":0.016398,"timeWriteBody":0.000171}
2020-11-17_23:36:08.75013 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"request","remoteAddr":"127.0.0.1:54256","reqBytes":46,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/users/current","reqQuery":"","time":"2020-11-17T23:36:08.750090562Z"}
2020-11-17_23:36:08.75848 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"response","remoteAddr":"127.0.0.1:54256","reqBytes":46,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/users/current","reqQuery":"","respBytes":617,"respStatus":"OK","respStatusCode":200,"time":"2020-11-17T23:36:08.758422725Z","timeToStatus":0.008324,"timeTotal":0.008329,"timeWriteBody":0.000005}
2020-11-17_23:36:08.76051 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"request","remoteAddr":"127.0.0.1:54258","reqBytes":358,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/links","reqQuery":"","time":"2020-11-17T23:36:08.760477553Z"}
2020-11-17_23:36:08.77003 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"response","remoteAddr":"127.0.0.1:54258","reqBytes":358,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/links","reqQuery":"","respBytes":87,"respStatus":"OK","respStatusCode":200,"time":"2020-11-17T23:36:08.769952984Z","timeToStatus":0.009413,"timeTotal":0.009468,"timeWriteBody":0.000056}
2020-11-17_23:36:08.77180 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"request","remoteAddr":"127.0.0.1:54260","reqBytes":154,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/groups","reqQuery":"","time":"2020-11-17T23:36:08.771773070Z"}
2020-11-17_23:36:08.77990 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"response","remoteAddr":"127.0.0.1:54260","reqBytes":154,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/groups","reqQuery":"","respBytes":88,"respStatus":"OK","respStatusCode":200,"time":"2020-11-17T23:36:08.779830111Z","timeToStatus":0.007995,"timeTotal":0.008050,"timeWriteBody":0.000055}
2020-11-17_23:36:08.78147 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"request","remoteAddr":"127.0.0.1:54262","reqBytes":220,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/groups","reqQuery":"","time":"2020-11-17T23:36:08.781425399Z"}
2020-11-17_23:36:08.79070 {"PID":88182,"RequestID":"req-4n7zt2yuoh2i252o0ygn","level":"info","msg":"response","remoteAddr":"127.0.0.1:54262","reqBytes":220,"reqForwardedFor":"172.17.0.1","reqHost":"10.0.0.166:8000","reqMethod":"POST","reqPath":"arvados/v1/groups","reqQuery":"","respBytes":107,"respStatus":"OK","respStatusCode":200,"time":"2020-11-17T23:36:08.790618414Z","timeToStatus":0.009127,"timeTotal":0.009186,"timeWriteBody":0.000059}
2020-11-17_23:36:08.92698 {"PID":88182,"RequestID":"req-9plyt6fg30rjmg8yoslm","level":"info","msg":"request","remoteAddr":"127.0.0.1:54266","reqBytes":0,"reqForwardedFor":"10.0.0.166","reqHost":"10.0.0.166:8000","reqMethod":"GET","reqPath":"discovery/v1/apis/arvados/v1/rest","reqQuery":"","time":"2020-11-17T23:36:08.926929301Z"}
2020-11-17_23:36:09.13794 {"PID":88182,"RequestID":"req-9plyt6fg30rjmg8yoslm","level":"info","msg":"response","remoteAddr":"127.0.0.1:54266","reqBytes":0,"reqForwardedFor":"10.0.0.166","reqHost":"10.0.0.166:8000","reqMethod":"GET","reqPath":"discovery/v1/apis/arvados/v1/rest","reqQuery":"","respBytes":185363,"respStatus":"OK","respStatusCode":200,"time":"2020-11-17T23:36:09.137819171Z","timeToStatus":0.209620,"timeTotal":0.210882,"timeWriteBody":0.001263}

notice the empty string in:

2020-11-17_23:36:08.73199 [req-4n7zt2yuoh2i252o0ygn]   Container Load (0.4ms)  SELECT  (octet_length(containers.mounts)) as read_length FROM "containers" WHERE (containers.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) ) AND (containers.uuid in ('','xsjpe-dz642-fu9pth30j364hm8','xsjpe-dz642-7wwe7g976v6l4ox','xsjpe-dz642-rr5tkzewia50xco','xsjpe-dz642-wkofonabvgm18xn')) ORDER BY containers.modified_at desc, containers.uuid LIMIT $1 OFFSET $2  [["LIMIT", 1000], ["OFFSET", 0]]

probably because the call was done with "\"requesting_container_uuid\",\"=\",null" ..?

#11 Updated by Nico César 11 months ago

that's from workbench

==> /etc/service/workbench/log/main/current <==
2020-11-18_00:02:54.76109 API client: 0.00566288 Prepare request GET https://10.0.0.166:8000/arvados/v1/users/current  {"reader_tokens"=>"[]", "_method"=>"GET", "_profile"=>"true"}
2020-11-18_00:02:54.77514 API client: 0.014113611 API transaction
2020-11-18_00:02:54.77517 Content-Encoding nil, Content-Length "617", actual content size 617
2020-11-18_00:02:54.77527 API client: 0.000193535 Parse response
2020-11-18_00:02:54.77564 API client: 0.000103723 Prepare request GET https://10.0.0.166:8000/discovery/v1/apis/arvados/v1/rest  {"reader_tokens"=>"[]", "_method"=>"GET", "_profile"=>"true"}
2020-11-18_00:02:54.79144 API client: 0.01569833 API transaction
2020-11-18_00:02:54.79149 API server: 0.007454 runtime reported
2020-11-18_00:02:54.79151 Content-Encoding nil, Content-Length nil, actual content size 185363
2020-11-18_00:02:54.79592 API client: 0.004555269 Parse response
2020-11-18_00:02:54.80284 API client: 0.000152438 Prepare request POST https://10.0.0.166:8000/arvados/v1/container_requests  {"reader_tokens"=>"[]", :_method=>"GET", :count=>"none", :order=>"[\"created_at desc\"]", :filters=>"[[\"requesting_container_uuid\",\"=\",null]]", :limit=>"12", :offset=>"0", "_profile"=>"true"}
2020-11-18_00:02:54.82506 API client: 0.022217086 API transaction
2020-11-18_00:02:54.82508 Content-Encoding nil, Content-Length nil, actual content size 24030
2020-11-18_00:02:54.82556 API client: 0.000552908 Parse response
2020-11-18_00:02:54.83096 API client: 0.000137383 Prepare request POST https://10.0.0.166:8000/arvados/v1/container_requests  {"reader_tokens"=>"[]", :_method=>"GET", :count=>"none", :order=>"[\"created_at desc\"]", :filters=>"[[\"requesting_container_uuid\",\"=\",null]]", :limit=>"6", :offset=>"6", "_profile"=>"true"}
2020-11-18_00:02:54.84199 API client: 0.010925423 API transaction
2020-11-18_00:02:54.84200 Content-Encoding nil, Content-Length "72", actual content size 72
2020-11-18_00:02:54.84202 API client: 0.000191325 Parse response
2020-11-18_00:02:54.84242 API client: 0.000190923 Prepare request POST https://10.0.0.166:8000/arvados/v1/containers  {"reader_tokens"=>"[]", :_method=>"GET", :where=>"{\"uuid\":[\"\",\"xsjpe-dz642-fu9pth30j364hm8\",\"xsjpe-dz642-7wwe7g976v6l4ox\",\"xsjpe-dz642-rr5tkzewia50xco\",\"xsjpe-dz642-wkofonabvgm18xn\"]}", :limit=>"9223372036854775807", :offset=>"0", "_profile"=>" 
2020-11-18_00:02:54.85998 API client: 0.01753942 API transaction
2020-11-18_00:02:54.86000 API server: 0.011612 runtime reported
2020-11-18_00:02:54.86004 Content-Encoding nil, Content-Length nil, actual content size 15267
2020-11-18_00:02:54.86042 API client: 0.00050245 Parse response
2020-11-18_00:02:54.86955 #<ActionView::Template::Error: argument to find() must be a uuid string. Acceptable formats: warehouse locator or string with format xxxxx-xxxxx-xxxxxxxxxxxxxxx>
2020-11-18_00:02:54.86961 /usr/src/arvados/apps/workbench/app/models/arvados_base.rb:205:in `find'
2020-11-18_00:02:54.86961 /usr/src/arvados/apps/workbench/app/models/container_work_unit.rb:14:in `initialize'
2020-11-18_00:02:54.86961 /usr/src/arvados/apps/workbench/app/models/container_request.rb:23:in `new'
2020-11-18_00:02:54.86961 /usr/src/arvados/apps/workbench/app/models/container_request.rb:23:in `work_unit'
2020-11-18_00:02:54.86962 /usr/src/arvados/apps/workbench/app/views/projects/_show_dashboard.html.erb:16:in `block in _app_views_projects__show_dashboard_html_erb___3216220718696381753_47226708474500'

#12 Updated by Peter Amstutz 11 months ago

  • Target version changed from 2020-11-18 to 2020-12-02 Sprint

#13 Updated by Tom Clegg 11 months ago

Nico César wrote:

  • The HasSuffix(k, "_at") block should have a "continue" at the end, and "expires_at" isn't needed in the switch statement below

This is odd... please look at 7670ec444f87d59b1c9151b2509cfd8e8facbd2c, for some reason the "case time.Time" is not covering that case. Am I missing a continue somewhere I can't see?

Looks like it's arriving as a string, not a time.Time, and we didn't handle that case in the 3rd case of the switch statement. This seems to fix it:

-                               tmp[k] = t.Format(rfc3339NanoFixed)
+                               if t.IsZero() {
+                                       tmp[k] = nil
+                               } else {
+                                       tmp[k] = t.Format(rfc3339NanoFixed)
+                               }
  • If we were already returning empty (non-nil) modified_by_client_uuid fields with no ill effects, we should keep doing so instead of making them null
  • Likewise I don't think we need to munge the description field, either, it's okay to return ""
  • We don't document whether "requesting_container_uuid" is null or empty, and python/javascript clients probably won't care either way, so I'm inclined to return "" and just make sure things still work well if a client copies the response into an update request and updates it to "" -- i.e., make sure Rails accepts "" to mean "none" in an update/create.
  • That leaves "output_uuid", and "log_uuid" which are documented to be null when not applicable, so I guess we do need to munge those
  • I think the comment "RoR returns nil instead of the Zero value" is misleading. The requirement is to make the response fit the client's expectations, which won't change when we stop using RoR (even though we can blame RoR for creating that expectation in the first place).

I bundle all this in one comment. Basically lib/controller/handler_test.go:TestGetObjects should be getting the same objects for RoR and for our CR in new codepath controller.... I know we can get better, but that would mean to change this particular test. I'm worried that change will end up biting us... I prefer to have a lot of explicit code that mimics still-in-use-legacy and a good comment to make whatever we need to make when sunsetting rails. I don't even mind starting a comment with SUNSETTING_RAILS_API:.... with explicit instructions what to do when that happens.

Does this makes sense to you?

Eliminating Rails and changing the public API are independent issues. The code in response.go is about the public API. So the comment could be

        // The following response fields are documented to use null
        // rather than "" to represent none/empty.

TestGetObjects is meant to alert us when we accidentally change the API responses by changing code in controller. It's just a development aid, though -- clients don't actually see the RailsAPI responses, so there's no functional requirement that they match the real (controller) responses.

Given how much yak shaving we're already doing, I'm reconsidering requesting_container_uuid -- maybe we should just change "" to null here. Fortunately, json.Unmarshal doesn't choke on null when expecting a string.

#14 Updated by Nico César 11 months ago

  • Target version deleted (2020-12-02 Sprint)
  • Looking at the relevant RailsAPI code for container request update/create calls, it seems like setting output_name="" causes the resulting collection name to be nil, while setting output_name=nil causes the collection name to be "Container #{out_type} for request #{uuid}". I think this is probably an accident and we should fix this in services/api/app/models/container_request.rb:197 so a nil output_name gets converted to "" on the way in, and "" invokes the automatic naming. Then we can update the docs to say "If null or empty". https://doc.arvados.org/v1.2/api/methods/container_requests.html

ok. noted... I'll add this to changes I'll do in later commits, I think some tests will have to be reviewed with this change

is this change

5c7576f6e

#16 Updated by Peter Amstutz 11 months ago

  • Target version set to 2020-12-16 Sprint

#17 Updated by Nico César 10 months ago

Added a test to show the problem we discussed in the chat 14d8b783f this will be the output:

What next? test lib/controller -test.v -gocheck.f TestIntermediateCluster
======= test lib/controller
=== RUN   Test
2020/12/04 20:11:16 THIS IS THE rcp.Conn.ContainerRequestCreate(): z2222

----------------------------------------------------------------------
FAIL: integration_test.go:538: IntegrationSuite.TestIntermediateCluster

user token: "v2/z1111-gj3su-80hxfod3lxhz6c5/1fb06th6r80lhnptcwmmavsab09z4z0m4hu7w7pgk8dthkwdkk" 
user UUID: "z1111-tpzed-6vytydzr5jyqfje" 
IntegrationSuite.TestIntermediateCluster Good token z1111 user sending a CR to z2222
integration_test.go:564:
    c.Check(err, check.IsNil)
... value *arvados.TransactionError = &arvados.TransactionError{Method:"POST", URL:url.URL{Scheme:"https", Opaque:"", User:(*url.Userinfo)(nil), Host:"127.0.0.11:44501", Path:"/arvados/v1/container_requests", RawPath:"", ForceQuery:false, RawQuery:"", Fragment:""}, StatusCode:401, Status:"401 Unauthorized", Errors:[]string{"request failed: https://127.0.0.22:46325/arvados/v1/container_requests: 401 Unauthorized: request failed: http://127.0.0.22:43581/arvados/v1/container_requests: 401 Unauthorized: Not logged in (req-18le1znt2tset1bhxj8p)"}} ("request failed: https://127.0.0.11:44501/arvados/v1/container_requests: 401 Unauthorized: request failed: https://127.0.0.22:46325/arvados/v1/container_requests: 401 Unauthorized: request failed: http://127.0.0.22:43581/arvados/v1/container_requests: 401 Unauthorized: Not logged in (req-18le1znt2tset1bhxj8p)")

integration_test.go:566:
    c.Check(cr.UUID, check.Not(check.Equals), "")
... obtained string = "" 
... expected string = "" 

OOPS: 0 passed, 1 FAILED
OK: 0 passed, 1 skipped
--- FAIL: Test (43.16s)
FAIL
exit status 1
FAIL    git.arvados.org/arvados.git/lib/controller    43.162s
======= lib/controller tests -- FAILED
======= test lib/controller -- 45s
Failures (1):
Fail: lib/controller tests (45s)
What next? 

Notice the "THIS IS THE rcp.Conn.ContainerRequestCreate(): z2222" but the lack of "THIS IS THE federation.Conn.ContainerRequestCreate() "

#18 Updated by Nico César 10 months ago

at 67ac5dcd79fa6f0549bb4f7646cb624e0baa60e5 systemRootToken has to be part of the request (added 500 Internal error if not in login.go)

but the test is still failing.

What next? test lib/controller -gocheck.vv -test.failfast -gocheck.f TestCreateRemoteContainerRequestCheckRuntimeToken
======= test lib/controller
START: federation_test.go:636: FederationSuite.TestCreateRemoteContainerRequestCheckRuntimeToken
START: federation_test.go:49: FederationSuite.SetUpTest
PASS: federation_test.go:49: FederationSuite.SetUpTest    0.003s

time="2020-12-08T23:25:53.911830473Z" level=info msg=request RequestID=req-93gdd81zbx5zptzl5wu8 remoteAddr="192.0.2.1:1234" reqBytes=174 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zmock" 
2020/12/08 23:25:53 THIS IS federation.Conn.ContainerRequestCreate() for zmock we are zzzzz
2020/12/08 23:25:53 THIS IS rcp.Conn.ContainerRequestCreate() for zmock we are zmock
time="2020-12-08T23:25:53.966631010Z" level=info msg=response RequestID=req-93gdd81zbx5zptzl5wu8 remoteAddr="192.0.2.1:1234" reqBytes=174 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zmock" respBytes=637 respStatus=OK respStatusCode=200 timeToStatus=0.054790 timeTotal=0.054794 timeWriteBody=0.000004
federation_test.go:664:
    c.Check(json.NewDecoder(s.remoteMockRequests[0].Body).Decode(&cr), check.IsNil)
... value *json.SyntaxError = &json.SyntaxError{msg:"invalid character 'c' looking for beginning of value", Offset:1} ("invalid character 'c' looking for beginning of value")

my gut instinct tells me that s.remoteMockRequests[0].Body is "cluster_id=zmock&container_request=%7B%22comman..." but I wasn't able to pin the problem down.

This is the body:

cluster_id=zmock&container_request=%7B%22command%22%3A%5B%22abc%22%5D%2C%22container_image%22%3A%22123%22%2C%22name%22%3A%22hello+world%22%2C%22output_path%22%3A%22%2F%22%2C%22runtime_token%22%3A%22v2%2Fzzzzz-gj3su-jstvbxd9za9vrmm%2F2axo05pbpyt26bc6lcor4ua5g9q1jh3aqqes9bkznt70cdm7x4%22%2C%22state%22%3A%22Uncommitted%22%7D

#19 Updated by Nico César 10 months ago

e6852ae4b 17014-controller-container-requests addressed #18 issues

#20 Updated by Nico César 10 months ago

f7165287f 17014-controller-container-requests https://ci.arvados.org/view/Developer/job/developer-run-tests/2222/

is the first commit to make all test pass.... depending on forceLegacyAPI14 we have different payloads in the mock. I tried to make them un-wrap the JSON object that contains the Container Request and test for what we're looking for

#21 Updated by Nico César 10 months ago

I created a clean branch with 1 commit

3764a1e0d2a31333344982478a9d6b861bc179a6 17014-controller-container-requests-take2

https://ci.arvados.org/view/Developer/job/developer-run-tests/2224/

Ready to review

#22 Updated by Nico César 10 months ago

  • Target version changed from 2020-12-16 Sprint to 2021-01-06 Sprint

#23 Updated by Tom Clegg 10 months ago

Do we need "omitempty" for SchedulingParameters > Preemptible, etc.? The disadvantage is that values like {API: false} will never be mentioned explicitly in an API response (or a request between controller and rails). I don't recall what the advantage is, though.

We need omitempty if we want to keep our test that they dont explicitly have those json objects.

lib/controller/federation_test.go:

Done and used Content-Type for that

Comments like "let's make sure the Runtime token is there" are just noise -- it doesn't seem to explain anything that's not clear from the c.Check() statement itself.

yeah, comments usually pop up when test fails, this is useful for people that are changing things

lib/controller/integration_test.go:

TestCreateContainerRequestWithBadToken():

You are correct, cleaned that up.

TestRuntimeTokenInCR():
  • conn1.ContainerRequestCreate(rootctx1, ...) -- this should be a user token/context.

Changed that and tests pass

lib/controller/localdb/login.go

Done.

5a5737ba7 17014-controller-container-requests-take2 https://ci.arvados.org/view/Developer/job/developer-run-tests/2232/

#24 Updated by Nico César 10 months ago

By doing this change:

diff --git a/sdk/go/arvados/container.go b/sdk/go/arvados/container.go
index d5f0b5bb1..dc08d8893 100644
--- a/sdk/go/arvados/container.go
+++ b/sdk/go/arvados/container.go
@@ -90,17 +90,17 @@ type Mount struct {
 // CPU) and network connectivity.
 type RuntimeConstraints struct {
        API          *bool `json:",omitempty"`
-       RAM          int64 `json:"ram,omitempty"`
-       VCPUs        int   `json:"vcpus,omitempty"`
-       KeepCacheRAM int64 `json:"keep_cache_ram,omitempty"`
+       RAM          int64 `json:"ram"`
+       VCPUs        int   `json:"vcpus"`
+       KeepCacheRAM int64 `json:"keep_cache_ram"`
 }

 // SchedulingParameters specify a container's scheduling parameters
 // such as Partitions
 type SchedulingParameters struct {
-       Partitions  []string `json:"partitions,omitempty"`
-       Preemptible bool     `json:"preemptible,omitempty"`
-       MaxRunTime  int      `json:"max_run_time,omitempty"`
+       Partitions  []string `json:"partitions"`
+       Preemptible bool     `json:"preemptible"`
+       MaxRunTime  int      `json:"max_run_time"`
 }

 // ContainerList is an arvados#containerList resource.

We get this error:

What next? test lib/controller -gocheck.vv -test.failfast -gocheck.f TestGetObjects
======= test lib/controller
START: handler_test.go:323: HandlerSuite.TestGetObjects
START: handler_test.go:47: HandlerSuite.SetUpTest
PASS: handler_test.go:47: HandlerSuite.SetUpTest    0.001s

handler_test.go:353:
    s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:314:
    c.Check(val, check.DeepEquals, direct[k],
        check.Commentf("RailsAPI %s key %q's value %q differs from controller's %q.", direct["kind"], k, direct[k], val))
... obtained map[string]interface {} = map[string]interface {}{"max_run_time":0, "partitions":interface {}(nil), "preemptible":false}
... expected map[string]interface {} = map[string]interface {}{}
... RailsAPI arvados#containerRequest key "scheduling_parameters"'s value map[] differs from controller's map["max_run_time":%!q(float64=0) "partitions":<nil> "preemptible":%!q(bool=false)].

handler_test.go:353:
    s.CheckObjectType(c, "/arvados/v1/"+url, arvadostest.AdminToken, skippedFields)
handler_test.go:314:
    c.Check(val, check.DeepEquals, direct[k],
        check.Commentf("RailsAPI %s key %q's value %q differs from controller's %q.", direct["kind"], k, direct[k], val))
... obtained map[string]interface {} = map[string]interface {}{"keep_cache_ram":0, "ram":123, "vcpus":1}
... expected map[string]interface {} = map[string]interface {}{"ram":123, "vcpus":1}
... RailsAPI arvados#containerRequest key "runtime_constraints"'s value map["ram":%!q(float64=123) "vcpus":%!q(float64=1)] differs from controller's map["keep_cache_ram":%!q(float64=0) "ram":%!q(float64=123) "vcpus":%!q(float64=1)].

START: handler_test.go:62: HandlerSuite.TearDownTest
PASS: handler_test.go:62: HandlerSuite.TearDownTest    0.000s

FAIL: handler_test.go:323: HandlerSuite.TestGetObjects

OOPS: 0 passed, 1 FAILED
START: handler_test.go:323: HandlerSuite.TestGetObjects
START: handler_test.go:47: HandlerSuite.SetUpTest
PASS: handler_test.go:47: HandlerSuite.SetUpTest    0.001s

START: handler_test.go:62: HandlerSuite.TearDownTest
PASS: handler_test.go:62: HandlerSuite.TearDownTest    0.000s

PASS: handler_test.go:323: HandlerSuite.TestGetObjects    0.326s

OK: 1 passed
--- FAIL: Test (0.70s)
FAIL
exit status 1
FAIL    git.arvados.org/arvados.git/lib/controller    0.702s
======= lib/controller tests -- FAILED
======= test lib/controller -- 4s
Failures (1):
Fail: lib/controller tests (4s)

#25 Updated by Nico César 10 months ago

After a conversation with TomC we'll be trying to eliminate "omitempty" and adjust the tests accordingly. Also removing a pointer from API field.

cf209afe7 17014-controller-container-requests-take2 https://ci.arvados.org/view/Developer/job/developer-run-tests/2234/

#26 Updated by Nico César 10 months ago

test_cancel_request_for_queued_container https://ci.arvados.org/job/developer-run-tests-apps-workbench-functionals/2274/console has this issue:

#<ArvadosApiClient::ApiErrorResponseException: request failed: https://127.0.0.1:44509/arvados/v1/container_requests/zzzzz-xvhdp-cr4queuedcontnr: 422 Unprocessable Entity: Runtime constraints cannot be modified in state 'Final' ({"vcpus"=>1, "ram"=>123}, {"api"=>false, "keep_cache_ram"=>0, "ram"=>123, "vcpus"=>1}) (req-3it2k4lc8gljogqtya4y); Scheduling parameters cannot be modified in state 'Final' ({}, {"max_run_time"=>0, "partitions"=>nil, "preemptible"=>false}) (req-3it2k4lc8gljogqtya4y) [API: 422]>
/usr/src/arvados/apps/workbench/app/models/arvados_api_client.rb:180:in `api'
/usr/src/arvados/apps/workbench/app/models/arvados_base.rb:332:in `save'
/usr/src/arvados/apps/workbench/app/models/arvados_base.rb:360:in `save!'
/usr/src/arvados/apps/workbench/app/models/arvados_base.rb:310:in `update_attributes!'
/usr/src/arvados/apps/workbench/app/controllers/container_requests_controller.rb:86:in `cancel'

the new change creates requests with values in fields that aren't expected after final.

#27 Updated by Nico César 10 months ago

this change:

--- a/lib/crunchrun/crunchrun.go
+++ b/lib/crunchrun/crunchrun.go
@@ -621,7 +621,7 @@ func (runner *ContainerRunner) SetupMounts() (err error) {
                return fmt.Errorf("output path does not correspond to a writable mount point")
        }
-       if wantAPI := runner.Container.RuntimeConstraints.API; needCertMount && wantAPI != nil && *wantAPI {
+       if wantAPI := runner.Container.RuntimeConstraints.API; needCertMount && wantAPI {
                for _, certfile := range arvadosclient.CertFiles {
                        _, err := os.Stat(certfile)
                        if err == nil {
----------------------------------------------------------------------
FAIL: crunchrun_test.go:1208: TestSuite.TestSetupMounts

crunchrun_test.go:1326:
    c.Check(cr.Binds, DeepEquals, []string{realTemp + "/keep1/tmp0:/keeptmp"})
... obtained []string = []string{"/tmp/crunchrun_test1-385879435/keep1/tmp0:/keeptmp", "/tmp/crunchrun_test2-211265390/ca-certificates.crt:/etc/arvados/ca-certificates.crt:ro"}
... expected []string = []string{"/tmp/crunchrun_test1-385879435/keep1/tmp0:/keeptmp"}

crunchrun_test.go:1350:
    c.Check(cr.Binds, DeepEquals, []string{realTemp + "/keep1/by_id/59389a8f9ee9d399be35462a0f92541c+53:/keepinp:ro",
        realTemp + "/keep1/tmp0:/keepout"})
... obtained []string = []string{"/tmp/crunchrun_test1-385879435/keep1/by_id/59389a8f9ee9d399be35462a0f92541c+53:/keepinp:ro", "/tmp/crunchrun_test1-385879435/keep1/tmp0:/keepout", "/tmp/crunchrun_test2-211265390/ca-certificates.crt:/etc/arvados/ca-certificates.crt:ro"}
... expected []string = []string{"/tmp/crunchrun_test1-385879435/keep1/by_id/59389a8f9ee9d399be35462a0f92541c+53:/keepinp:ro", "/tmp/crunchrun_test1-385879435/keep1/tmp0:/keepout"}

crunchrun_test.go:1376:
    c.Check(cr.Binds, DeepEquals, []string{realTemp + "/keep1/by_id/59389a8f9ee9d399be35462a0f92541c+53:/keepinp:ro",
        realTemp + "/keep1/tmp0:/keepout"})
... obtained []string = []string{"/tmp/crunchrun_test1-385879435/keep1/by_id/59389a8f9ee9d399be35462a0f92541c+53:/keepinp:ro", "/tmp/crunchrun_test1-385879435/keep1/tmp0:/keepout", "/tmp/crunchrun_test2-211265390/ca-certificates.crt:/etc/arvados/ca-certificates.crt:ro"}
... expected []string = []string{"/tmp/crunchrun_test1-385879435/keep1/by_id/59389a8f9ee9d399be35462a0f92541c+53:/keepinp:ro", "/tmp/crunchrun_test1-385879435/keep1/tmp0:/keepout"}

crunchrun_test.go:1399:
    c.Check(cr.Binds, DeepEquals, []string{realTemp + "/json2/mountdata.json:/mnt/test.json:ro"})
... obtained []string = []string{"/tmp/crunchrun_test1-385879435/json2/mountdata.json:/mnt/test.json:ro", "/tmp/crunchrun_test2-211265390/ca-certificates.crt:/etc/arvados/ca-certificates.crt:ro"}
... expected []string = []string{"/tmp/crunchrun_test1-385879435/json2/mountdata.json:/mnt/test.json:ro"}

crunchrun_test.go:1399:
    c.Check(cr.Binds, DeepEquals, []string{realTemp + "/json2/mountdata.json:/mnt/test.json:ro"})
... obtained []string = []string{"/tmp/crunchrun_test1-385879435/json2/mountdata.json:/mnt/test.json:ro", "/tmp/crunchrun_test2-211265390/ca-certificates.crt:/etc/arvados/ca-certificates.crt:ro"}
... expected []string = []string{"/tmp/crunchrun_test1-385879435/json2/mountdata.json:/mnt/test.json:ro"}

crunchrun_test.go:1399:
    c.Check(cr.Binds, DeepEquals, []string{realTemp + "/json2/mountdata.json:/mnt/test.json:ro"})
... obtained []string = []string{"/tmp/crunchrun_test1-385879435/json2/mountdata.json:/mnt/test.json:ro", "/tmp/crunchrun_test2-211265390/ca-certificates.crt:/etc/arvados/ca-certificates.crt:ro"}
... expected []string = []string{"/tmp/crunchrun_test1-385879435/json2/mountdata.json:/mnt/test.json:ro"}

crunchrun_test.go:1427:
    c.Check(cr.Binds, DeepEquals, []string{realTemp + "/text2/mountdata.text:/mnt/test.txt:ro"})
... obtained []string = []string{"/tmp/crunchrun_test1-385879435/text2/mountdata.text:/mnt/test.txt:ro", "/tmp/crunchrun_test2-211265390/ca-certificates.crt:/etc/arvados/ca-certificates.crt:ro"}
... expected []string = []string{"/tmp/crunchrun_test1-385879435/text2/mountdata.text:/mnt/test.txt:ro"}

crunchrun_test.go:1455:
    c.Check(cr.Binds, DeepEquals, []string{realTemp + "/tmp2:/tmp", realTemp + "/keep1/tmp0:/tmp/foo:ro"})
... obtained []string = []string{"/tmp/crunchrun_test1-385879435/tmp2:/tmp", "/tmp/crunchrun_test1-385879435/keep1/tmp0:/tmp/foo:ro", "/tmp/crunchrun_test2-211265390/ca-certificates.crt:/etc/arvados/ca-certificates.crt:ro"}
... expected []string = []string{"/tmp/crunchrun_test1-385879435/tmp2:/tmp", "/tmp/crunchrun_test1-385879435/keep1/tmp0:/tmp/foo:ro"}

#28 Updated by Tom Clegg 10 months ago

Nico César wrote:

the new change creates requests with values in fields that aren't expected after final.

Might be easiest to fix this in RailsAPI -- changing runtime_constraints from {} (implied zero value) to {api: false} (explicit zero value) can just be ignored when CR state is final.

#29 Updated by Nico César 10 months ago

Tom Clegg wrote:

Nico César wrote:

the new change creates requests with values in fields that aren't expected after final.

Might be easiest to fix this in RailsAPI -- changing runtime_constraints from {} (implied zero value) to {api: false} (explicit zero value) can just be ignored when CR state is final.

f693516a9 17014-controller-container-requests-take2 https://ci.arvados.org/view/Developer/job/developer-run-tests/2238/

#30 Updated by Nico César 10 months ago

After a good hacking day with Lucas, we came into this:

https://github.com/rails/rails/issues/34537#issuecomment-442265161

Looks that this comment is accurate: "Maybe it is because we don't want to diff hashes for performance reasons?", so out jsonb attributes. In container request runtime_constraint and schedule_parameters are JSONB (but there are ripples in the water for command and mounts too).

5a5737ba had an elegant solution by adding omitempty on those fields, but if we want to remove them we need to walk the path that we did in 22895df84 and after...

#31 Updated by Nico César 9 months ago

I did the changes we discussed after standup today (were the CR has a preemtible value that is a bool type) and this is af2ce3cfa

The test failed. see https://ci.arvados.org/job/developer-run-tests-services-api/2353/console

Failure:
ContainerRequestTest#test_having_Rails.configuration.Containers.UsePreemptibleInstances=false,_non-child_CR_should_not_ask_for_preemptible_instance_by_default [/usr/src/arvados/services/api/test/unit/container_request_test.rb:1040]:
Expected false to be nil.

This is because now the default value is explicit.

#32 Updated by Nico César 9 months ago

I had to change a couple tests to fit into the new default values

2879be603 (branch 17014-controller-container-requests-take2)

All blue balls: https://ci.arvados.org/view/Developer/job/developer-run-tests/2248/

#33 Updated by Tom Clegg 9 months ago

I found the forget_innocuous_serialized_fields_updates / set_zero_values unduly hard to follow, and it was changing the preemptible behavior in a way I don't think we wanted (changing explicit true to false).

I think I found the magic Rails spell for altering the record in after_find and making the changed/changes/*_was facilities report that nothing has changed:
  1. modify the attr
  2. set_attribute_was('attr', attr())
  3. clear_changes_information()

(Aside: I noticed ContainerRequest#get_requesting_container seems to return either a UUID or a container object depending on whether the answer is already cached, which I'm pretty sure is a mistake, but it doesn't seem to break anything in practice so I didn't change it.)

17014-controller-container-requests-take2 @ a2ae9be785bdc066c74a6157f921b07638807fbe -- https://ci.arvados.org/view/Developer/job/developer-run-tests/2251/

#34 Updated by Peter Amstutz 9 months ago

  • Target version changed from 2021-01-06 Sprint to 2021-01-20 Sprint

#35 Updated by Nico César 9 months ago

  • Target version deleted (2021-01-20 Sprint)

#36 Updated by Tom Clegg 9 months ago

@ 87237527d

There's a FIXME in source:lib/controller/federation/conn.go, token needs to be time-limited. The easiest way I see is to add an expires_at param to user_sessions#create in RailsAPI, and set the new token's expiry to min(params[:expires_at], now+config.tokenlifetime) ... and pass now+blobsigningttl as that param on the controller side.

Perhaps something went wrong in squash/rebase? The new commit adds some duplicate entries in source:services/api/test/fixtures/container_requests.yml.

This comment in source:lib/controller/federation_test.go ends abruptly:

+// getCRfromMockRequest returns a ContainerRequest with the content of

Nit: Godoc comments should be full sentences with punctuation.

#38 Updated by Tom Clegg 9 months ago

In lib/controller/integration_test.go: is there a reason for the 1h expiry? Seems harmless but also perhaps left in by accident?

In lib/controller/rpc/conn.go: it seems like "case time.Time" and "case *time.Time" are unreachable, since params comes from json.Unmarshal. And is there really a case where a time string isn't 0001-01-01 but does unmarshal to a zero time? Could this whole switch statement reduce to if v, ok := v.(string); ok && strings.HasPrefix(v, "0001-01-01T00:00:00") { tmp[k]=nil } ?

In lib/controller/rpc/conn.go: the copy-pasted comment about rfc3339NanoFixed should be updated to indicate the real reason we're doing this (change zero times to nil).

In lib/controller/rpc/conn.go: looks like you added and then removed the code that went with the new comment "// if ExpiresAt is empty value then add 2 hour expiration"

In services/api/app/controllers/user_sessions_controller.rb: does anything send this param? Passing it through seems harmless but also kind of mysterious.

return send_api_token_to(params[:return_to], current_user, params[:remote], params[:expires_at])

The new tests seem very copy-pastey. Could do a parameterized test:

[[0, 1.hour, 1.hour],
 [1.hour, 2.hour, 1.hour],
 [2.hour, 1.hour, 1.hour],
 [2.hour, nil, 2.hour],
].each do |config_lifetime, request_lifetime, expect_lifetime|
  ...
end

Probably want to squash commits since 3203d60c, there's a fair bit of adding+removing that probably won't be helpful for archaeology.

#39 Updated by Nico César 9 months ago

Tom Clegg wrote:

In lib/controller/integration_test.go: is there a reason for the 1h expiry? Seems harmless but also perhaps left in by accident?

It worked as expected and is harmless. I prefer to to keep it just to see if in the future that test exercises something that isnt "the default" that we always have cases covering it.

In lib/controller/rpc/conn.go: it seems like "case time.Time" and "case *time.Time" are unreachable, since params comes from json.Unmarshal. And is there really a case where a time string isn't 0001-01-01 but does unmarshal to a zero time? Could this whole switch statement reduce to if v, ok := v.(string); ok && strings.HasPrefix(v, "0001-01-01T00:00:00") { tmp[k]=nil } ?

I agree. Look at f37a98d95

In lib/controller/rpc/conn.go: the copy-pasted comment about rfc3339NanoFixed should be updated to indicate the real reason we're doing this (change zero times to nil).

done.

In lib/controller/rpc/conn.go: looks like you added and then removed the code that went with the new comment "// if ExpiresAt is empty value then add 2 hour expiration"

that back and forth was because I wanted to see how the railsapi side of it was procesing it (and shared with Lucas). I took it out since I don't think we need noise there. Specially now that we know that we honor TokenLifetime correctly

In services/api/app/controllers/user_sessions_controller.rb: does anything send this param? Passing it through seems harmless but also kind of mysterious. [...]

The new tests seem very copy-pastey. Could do a parameterized test:

[...]

I agree. Look at f37a98d95

Probably want to squash commits since 3203d60c, there's a fair bit of adding+removing that probably won't be helpful for archaeology.

yeah, I'll push what we have so you can see f37a98d95 by itself. then squash all the rest if we're happy to merge

#41 Updated by Tom Clegg 9 months ago

Nico César wrote:

Tom Clegg wrote:

In lib/controller/integration_test.go: is there a reason for the 1h expiry? Seems harmless but also perhaps left in by accident?

It worked as expected and is harmless. I prefer to to keep it just to see if in the future that test exercises something that isnt "the default" that we always have cases covering it.

I'm not convinced it's a good idea. We're not actually checking that the non-zero value works, it's not an appropriate place to do such a check, and it doesn't seem to match a real-life use case. We already have unit tests to check non-default values -- I think we should stick with normal/default values when setting up the generic integration testing environment.

In lib/controller/rpc/conn.go: looks like you added and then removed the code that went with the new comment "// if ExpiresAt is empty value then add 2 hour expiration"

that back and forth was because I wanted to see how the railsapi side of it was procesing it (and shared with Lucas). I took it out since I don't think we need noise there. Specially now that we know that we honor TokenLifetime correctly

Sorry, my note was unclear. I meant we should remove that comment, because it's incorrect now.

In services/api/app/controllers/user_sessions_controller.rb: does anything send this param? Passing it through seems harmless but also kind of mysterious. [...]

return send_api_token_to(params[:return_to], current_user, params[:remote], params[:expires_at])

?

The new tests seem very copy-pastey. Could do a parameterized test:

I agree. Look at f37a98d95

Much better, thanks!

#42 Updated by Nico César 9 months ago

did a big squash and left 882bfd2383da for you to review

https://ci.arvados.org/job/developer-run-tests/2268/

You'll need to do a --force to pull it.

#43 Updated by Tom Clegg 9 months ago

882bfd238 LGTM, thanks!

#44 Updated by Anonymous 9 months ago

  • % Done changed from 0 to 100
  • Status changed from In Progress to Resolved

#45 Updated by Nico César 9 months ago

Final merge has all test passing: https://ci.arvados.org/view/All/job/run-tests/4318/

#46 Updated by Peter Amstutz 5 months ago

  • Release set to 38

Also available in: Atom PDF