Arvados

Some formatting difference that makes operator life much easier

$ arvados-server cloudtest
[ACTION] req-12345 getting instance list
[INFO] req-12345 got instance list (N=13) ## <--- here "N=13" is some information, but probably we'll need to have more, unsure about the format (N=..)
[WARN] no instances are tagged with our InstanceSetID (7 instances are not tagged with any InstanceSetID at all)
[ACTION] req-12346 creating instance with tags CloudTestPID:1234, InstanceSetID:cloudtest-ops@4xphq   ## <- map[] is a implementation detail in golang
[INFO] req-12346 created instance with id i-12345abcde
[CHECK] all requested tags are present
[ACTION] req-12347 getting instance list
[INFO] req-12347 got instance list (N=14)
[CHECK] found our instance i-12345abcde in returned list
[CHECK] all requested tags are present
[WARN] instance has no address
[INFO] waiting probeInterval 10s
[ACTION] req-12348 getting instance list
[INFO] req-12348 got instance list (N=14)
[CHECK] instance i-12345abcde  has address 10.2.3.4 ## <- Is always good to be able to grep for i-12345abcde  

[ACTION] req-12349 executing command "true" on i-12345abcde addr 10.2.3.4 port 2222 ## <--- what is command "true" ? is it a bash command..? 
[WARN] req-12349 executing command failed: connection refused ## <-- WARN? ... is this "expected"...? maybe INFO with "tries 1 out of 5" kind of message
[INFO] waiting probeInterval 10s
[ACTION] req-12350 executing command "true" on i-12345abcde addr 10.2.3.4 port 2222
[INFO] req-12350 executing command failed: connection refused (tries: 2/5)  ##  <-- like this.
[INFO] waiting probeInterval 10s
[ACTION] req-12351 executing command "true" on i-12345abcde addr 10.2.3.4 port 2222
[INFO] req-12351 executing command succeeded
[ACTION] req-12352 destroying instance i-12345abcde
[INFO] req-12352 destroyed instance i-12345abcde

(..)

[ACTION] req-12360 getting instance list
[INFO] req-12360 got instance list (N=14)
[ERROR] req-12360instance i-12345abcde not found in returned list

15026-cloudtest @ 0684f84ec50069b24b4564474db67d6b44266699 -- https://ci.curoverse.com/view/Developer/job/developer-run-tests/1337/

• Log uses logrus "text" format, with timestamps and info/error loglevels
• Shell command isn't connected to caller's stdin/stdout/stderr: it has no stdin, and stdout/stderr are buffered and reported as log fields instead. This can be changed with a few changes to our "executor" interface, but I'm not sure how important it is: if we get this far we've already satisfied the primary goal here, and we already provide a much more flexible option for doing stuff on the test instance: use -pause-before-destroy and run remote commands with normal tools (ssh).
• Renamed -clear to -destroy-existing
• Added -image-id and -instance-type command line options (default instance type is the cheapest one in the config)

This needs its own page in the admin section of the docs, which should be linked with install-dispatch-cloud.html.

In refreshTestInstance()

        t.testInstance = worker.TagVerifier{i, t.secret}

I also see this in Run()

    t.testInstance = worker.TagVerifier{t.testInstance, t.secret}

Is this redundantly wrapping testInstance with TagVerifier twice?

Instead of directly running a shell command on the instance, it would be more useful to have "run a local command" passing along the instance type and host:port on the command line. The local script could call ssh and do what it likes. This would enable testing tasks like "try each instance type, make sure it works, then log in and record the RAM and disk space on the actually booted instance." Right now an admin would have to do that manually, or by capturing and parsing the output of cloud-test.

For the benefit of admins, maybe the logging could treat each logical step in the process of bringing up a cloud node as a test and print "PASSED: node appeared on the instance list" or "FAILED: boot probe command did not succeed"

If the boot probe fails, that should be a deferred error. That seems like an obvious situation where the admin wants to log in to the instance and find out why.

Peter Amstutz wrote:

Is this redundantly wrapping testInstance with TagVerifier twice?

Ah, yes. In the "successful create()" case it was getting wrapped twice. Harmless, but confusing. Fixed.

Instead of directly running a shell command on the instance, it would be more useful to have "run a local command" passing along the instance type and host:port on the command line. The local script could call ssh and do what it likes. This would enable testing tasks like "try each instance type, make sure it works, then log in and record the RAM and disk space on the actually booted instance." Right now an admin would have to do that manually, or by capturing and parsing the output of cloud-test.

I think the stdout/stderr changes I mentioned above (note-16) would achieve this ("cloudtest -command 'cat /proc/meminfo' >meminfo.txt") without taking on the challenge of templating the private key/host/port into a given command line.

We're really here to test cloud drivers/configs in order to unblock arvados-dispatch-cloud production use. The "execute shell command" thing is already a "nice easy thing we might as well add" so I'm reluctant to creep scope further.

For the benefit of admins, maybe the logging could treat each logical step in the process of bringing up a cloud node as a test and print "PASSED: node appeared on the instance list" or "FAILED: boot probe command did not succeed"

I'm not quite following the benefit here. I guess seeing a few "PASS" among the "INFO" could be encouraging? We already have "FAILED", except that it's spelled "ERROR"...? I'm imagining the typical user will ignore everything and look out for ERROR and/or non-zero exit, and dig through the rest of the logs if the error message isn't enough to troubleshoot.

If the actions were independent, as they are in a unit test suite, "look at the log entries between the most recent PASS and the error" would be a time-saver, but I'm not sure that approach really works here.

If the boot probe fails, that should be a deferred error. That seems like an obvious situation where the admin wants to log in to the instance and find out why.

Ah, yes. Fixed. This also means the shell command gets attempted, which seems better (or at least not worse).

Same change for "tags weren't saved/loaded properly" -- might as well still wait for boot and try the rest of the stuff, right?

15026-cloudtest @ e61d0c92e9f52c8db5e65026a551f62918aad1b4 -- https://ci.curoverse.com/view/Developer/job/developer-run-tests/1346/

• Copy wiki page Cloudtest utility to admin docs
• Report duration of remote operations when logging success/error

Tom Clegg wrote:

I'm not quite following the benefit here. I guess seeing a few "PASS" among the "INFO" could be encouraging? We already have "FAILED", except that it's spelled "ERROR"...? I'm imagining the typical user will ignore everything and look out for ERROR and/or non-zero exit, and dig through the rest of the logs if the error message isn't enough to troubleshoot.

If the actions were independent, as they are in a unit test suite, "look at the log entries between the most recent PASS and the error" would be a time-saver, but I'm not sure that approach really works here.

The documentation says:

1. Create a new instance
2. Wait for it to finish booting
3. Run a shell command on the new instance (optional)
4. Pause while you log in to the new instance and do other tests yourself (optional)
5. Shut down the instance

So my thought is that it would be nice if the logs divided it up what it is doing into phases corresponding to the documentation, so that the admin can follow along specifically what each step is trying to accomplish.

INFO[] Step 1: creating instance
INFO[] Step 1 passed: created instance
INFO[] Step 2: Wait for it to finish booting
INFO[] Step 2 passed: found our instance in returned list
...

But if you don't think that worth the effort, I won't hold up the review over it (LGTM).

• doc page
• log duration of create/destroy/list/run ops

15026-cloudtest @ b13f1f4222fc0a211d9f03d4078353ef11900907

...with 2x notextile tags added to fix the escaped <span ...> stuff.

In the code for logging duration:

        lgr := t.Logger.WithField("Instance", t.testInstance.ID())
        if lgr := lgr.WithField("Duration", time.Since(t0)); err != nil {
            lgr.WithError(err).Error("error destroying instance")

What's happening here with embedding "lgr" in the "if" statement? Is that aliasing "lgr" so that it has the "Duration" field inside the "if" block but not in the code following it? Maybe rename the inner variable to avoid confusion?

Otherwise LGTM.

Peter Amstutz wrote:

What's happening here with embedding "lgr" in the "if" statement? Is that aliasing "lgr" so that it has the "Duration" field inside the "if" block but not in the code following it? Maybe rename the inner variable to avoid confusion?

Yes, exactly. Will rename.

The Azure driver uses the InstanceSetID for things that have restrictions.

arvados-server cloudtest

arvados-server cloudtest -instance-set-id cloudtest-root_c97qk.arvadosapi.com

arvados-server cloudtest -instance-set-id cloudtest-root-c97qk.arvadosapi.com

→success

The cloud.Driver code promises the InstanceSetID will be "of the form "zzzzz-zzzzz-zzzzzzzzzzzzzzz" where each z can be any alphanum"... so maybe cloudtest's default should be something like "zzzzz-zzzzz-zzzzzzcloudtest"?

(The root@hostname thing was supposed to make the default behavior "notice if previous runs left instances lying around, but don't mess with another host's concurrent tests" -- but it's so easy for the operator to achieve that with a command line/script that less built-in cleverness is probably better.)

Tom Clegg wrote:

The cloud.Driver code promises the InstanceSetID will be "of the form "zzzzz-zzzzz-zzzzzzzzzzzzzzz" where each z can be any alphanum"... so maybe cloudtest's default should be something like "zzzzz-zzzzz-zzzzzzcloudtest"?

Yes. Especially if that is part of the interface contract. Maybe the admin should be required to provide one in that form as well?