Project

General

Profile

Actions

Feature #17014

closed

Add Container Requests endpoint to controller

Added by Nico César over 3 years ago. Updated almost 3 years ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Category:
API
Target version:
-
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 1 (0 open1 closed)

Task #17036: Review 17014-controller-container-requests-take2ResolvedNico César11/10/2020Actions

Related issues

Related to Arvados - Bug #17053: Integration test failing ClosedNico CésarActions
Related to Arvados Epics - Idea #9053: Port API server to GoNewActions
Blocks Arvados - Feature #16462: Expand arvados-controller to expose forecast featuresNewActions
Actions #1

Updated by Peter Amstutz over 3 years ago

  • Status changed from New to In Progress
Actions #2

Updated by Peter Amstutz over 3 years ago

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

Updated by Nico César over 3 years ago

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

Updated by Nico César over 3 years ago

  • Related to Bug #17053: Integration test failing added
Actions #5

Updated by Nico César over 3 years ago

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

Updated by Nico César over 3 years ago

branch 17014-controller-container-requests has commit 9e312753855286a7e21c83218bb48589f4d1535d as soon as developer-run-tests: #2172 is done is ready for review

Actions #7

Updated by Nico César over 3 years ago

  • Related to Idea #9053: Port API server to Go added
Actions #8

Updated by Tom Clegg over 3 years 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.

Actions #9

Updated by Nico César over 3 years ago

I commited 7670ec444f87d59b1c9151b2509cfd8e8facbd2c test: 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.

Actions #10

Updated by Nico César over 3 years 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" ..?

Actions #11

Updated by Nico César over 3 years 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'

Actions #12

Updated by Peter Amstutz over 3 years ago

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

Updated by Tom Clegg over 3 years 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.

Actions #14

Updated by Nico César over 3 years 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

Actions #16

Updated by Peter Amstutz over 3 years ago

  • Target version set to 2020-12-16 Sprint
Actions #17

Updated by Nico César over 3 years 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() "

Actions #18

Updated by Nico César over 3 years 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
Actions #19

Updated by Nico César over 3 years ago

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

Actions #20

Updated by Nico César over 3 years ago

f7165287f 17014-controller-container-requests 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

Actions #21

Updated by Nico César over 3 years ago

I created a clean branch with 1 commit

3764a1e0d2a31333344982478a9d6b861bc179a6 17014-controller-container-requests-take2

developer-run-tests: #2224

Ready to review

Actions #22

Updated by Nico César over 3 years ago

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

Updated by Tom Clegg over 3 years 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 developer-run-tests: #2232

Actions #24

Updated by Nico César over 3 years 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)

Actions #25

Updated by Nico César over 3 years 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 developer-run-tests: #2234

Actions #26

Updated by Nico César over 3 years ago

test_cancel_request_for_queued_container 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.

Actions #27

Updated by Nico César over 3 years 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"}

Actions #28

Updated by Tom Clegg over 3 years 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.

Actions #29

Updated by Nico César over 3 years 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 developer-run-tests: #2238

Actions #30

Updated by Nico César over 3 years 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...

Actions #31

Updated by Nico César over 3 years 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 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.

Actions #32

Updated by Nico César over 3 years 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: developer-run-tests: #2248

Actions #33

Updated by Tom Clegg over 3 years 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 -- developer-run-tests: #2251

Actions #34

Updated by Peter Amstutz over 3 years ago

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

Updated by Nico César over 3 years ago

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

87237527d78621513fb73f619d2b3f49e84451c5 17014-controller-container-requests-take3

is ready for review

developer-run-tests: #2252

Actions #36

Updated by Tom Clegg over 3 years 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.

Actions #37

Updated by Nico César over 3 years ago

7c3bc0685d120eab7365fc18c06a174427c92312
branch 17014-controller-container-requests-take3,
developer-run-tests: #2264

Actions #38

Updated by Tom Clegg over 3 years 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.

Actions #39

Updated by Nico César about 3 years 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

Actions #41

Updated by Tom Clegg about 3 years 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!

Actions #42

Updated by Nico César about 3 years ago

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

developer-run-tests: #2268

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

Actions #43

Updated by Tom Clegg about 3 years ago

882bfd238 LGTM, thanks!

Actions #44

Updated by Anonymous about 3 years ago

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

Updated by Nico César about 3 years ago

Final merge has all test passing: run-tests: #4318

Actions #46

Updated by Peter Amstutz almost 3 years ago

  • Release set to 38
Actions

Also available in: Atom PDF