Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

csi: volume-consuming tasks fail after client restart #7200

Closed
tgross opened this issue Feb 19, 2020 · 3 comments
Closed

csi: volume-consuming tasks fail after client restart #7200

tgross opened this issue Feb 19, 2020 · 3 comments
Assignees
Milestone

Comments

@tgross
Copy link
Member

tgross commented Feb 19, 2020

This is an early in-development bug for CSI that I want to make sure we track down before we go into testing.

When a Nomad client is restarted, tasks consuming a volume on that client will fail when Nomad tries to reattach to them, saying it can't find the plugin. When the scheduler re-schedules the alloc, everything works fine. (I would suspect a race condition here between when the plugin alloc is reattached and the consuming alloc is, but it looks like at least in this case the plugin alloc was reattached first.)

Plugin job
job "csi-something" {
  datacenters = ["dc1"]

  group "csi" {
    task "plugin" {
      driver = "docker"

      config {
        image = "quay.io/k8scsi/hostpathplugin:v1.2.0"

        args = [
          "--drivername=csi-hostpath",
          "--v=5",
          "--endpoint=unix://csi/csi.sock",
          "--nodeid=foo",
        ]

        /* privileged = true */
      }

      csi_plugin {
        id        = "csi-hostpath"
        type      = "monolith"
        mount_dir = "/csi"
      }

      resources {
        cpu    = 500
        memory = 256

        network {
          mbits = 10
          port  "plugin"{}
        }
      }
    }
  }
}
Example volume-consuming job
job "example" {
  datacenters = ["dc1"]
  group "cache" {
    volume "test" {
      type   = "csi"
      source = "UUID"
    }
    task "redis" {
      driver = "docker"
      config {
        image = "redis:3.2"
        port_map {
          db = 6379
        }
      }
      volume_mount {
        volume      = "test"
        destination = "/test"
      }
      resources {
        cpu    = 500
        memory = 256
        network {
          mbits = 14
          port  "db"  {}
        }
      }
    }
  }
}

Repro, running Nomad current to f-csi-volumes (as of this writing) under systemd on Linux:

export CSI_ENDPOINT="/var/nomad/client/csi/monolith/csi-hostpath/csi.sock"
nomad run plugin.nomad
sleep 10
sudo csc --endpoint $CSI_ENDPOINT controller create-volume test-volume --cap 1,2,ext4

# ^ get the UUID

curl -XPUT "http://localhost:4646/v1/csi/volume/UUID" -d '{"Volumes": [
  {
    "ID": "1ca7a1ab-5355-11ea-9a53-0242ac110002",
    "Namespace": "default",
    "AccessMode": "single-node-writer",
    "AttachmentMode": "file-system",
    "PluginID": "csi-hostpath"
  }
]}'

# make sure we can get the volume back out
curl -s "http://localhost:4646/v1/csi/volume/UUID" | jq .
{
  "AccessMode": "single-node-writer",
  "AttachmentMode": "file-system",
  "ControllerRequired": false,
  "ControllersExpected": 1,
  "ControllersHealthy": 1,
  "CreateIndex": 45,
  "Healthy": true,
  "ID": "UUID",
  "ModifyIndex": 45,
  "Namespace": "default",
  "NodesExpected": 1,
  "NodesHealthy": 1,
  "PluginID": "csi-hostpath",
  "ReadAllocs": null,
  "ResourceExhausted": null,
  "Topologies": null,
  "VolumeGC": null,
  "WriteAllocs": null
}

# run the job
nomad job run example.nomad

# verify the job is up and running and healthy, with the /test dir mounted
nomad alloc status ...
nomad alloc exec ...

Then restart Nomad with sudo systemctl restart nomad. The example job will fail:

Recent Events:
Time                  Type           Description
2020-02-19T20:36:21Z  Killing        Sent interrupt. Waiting 5s before force killing
2020-02-19T20:36:21Z  Setup Failure  failed to setup alloc: pre-run hook "csi_hook" failed: Plugin not found
2020-02-19T20:33:35Z  Started        Task started by client
2020-02-19T20:33:34Z  Task Setup     Building Task Directory
2020-02-19T20:33:34Z  Received       Task received by client
Trace log outputs from journalctl
[TRACE] client.alloc_runner: running pre-run hooks: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 start="2020-02-19 20:40:15.994750452 +0000 UTC m=+4.174783826"
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=alloc_dir start="2020-02-19 20:40:15.996122991 +0000 UTC m=+4.17615
[DEBUG] client.driver_mgr.docker.docker_logger: plugin process exited: driver=docker path=/opt/gopath/bin/nomad pid=30188
[DEBUG] client.driver_mgr.docker.docker_logger: plugin exited: driver=docker
[TRACE] client.alloc_runner: running pre-run hooks: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 start="2020-02-19 20:40:15.995395277 +0000 UTC m=+4.175428690"
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=alloc_dir start="2020-02-19 20:40:15.996806046 +0000 UTC m=+4.17683
[TRACE] client.alloc_runner: alloc terminal; not running: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e desired_status=run client_status=failed
[DEBUG] client: updated allocations: index=98 total=3 pulled=1 filtered=2
[DEBUG] client: allocation updates: added=0 removed=0 updated=1 ignored=2
[TRACE] client: updating alloc: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e index=90
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=alloc_dir end="2020-02-19 20:40:16.001413725 +0000 UTC m=+4.181447
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=await_previous_allocations start="2020-02-19 20:40:16.001432647 +00
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=await_previous_allocations end="2020-02-19 20:40:16.001446518 +000
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=migrate_disk start="2020-02-19 20:40:16.001483238 +0000 UTC m=+4.18
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=migrate_disk end="2020-02-19 20:40:16.001489837 +0000 UTC m=+4.181
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=alloc_health_watcher start="2020-02-19 20:40:16.0014958 +0000 UTC m
[TRACE] client.alloc_runner.runner_hook.alloc_health_watcher: not watching; already has health set: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=alloc_health_watcher end="2020-02-19 20:40:16.001504706 +0000 UTC
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=network start="2020-02-19 20:40:16.001510052 +0000 UTC m=+4.1815434
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=network end="2020-02-19 20:40:16.00151479 +0000 UTC m=+4.181548156
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=group_services start="2020-02-19 20:40:16.001521963 +0000 UTC m=+4.
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=group_services end="2020-02-19 20:40:16.001527509 +0000 UTC m=+4.1
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=consul_socket start="2020-02-19 20:40:16.00153265 +0000 UTC m=+4.18
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=consul_socket end="2020-02-19 20:40:16.001537015 +0000 UTC m=+4.18
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=csi_hook start="2020-02-19 20:40:16.001542268 +0000 UTC m=+4.181575
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 name=csi_hook end="2020-02-19 20:40:16.001546741 +0000 UTC m=+4.1815801
[TRACE] client.alloc_runner: finished pre-run hooks: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 end="2020-02-19 20:40:16.001551385 +0000 UTC m=+4.181584751" duration=
[TRACE] client.alloc_runner.task_runner: running prestart hooks: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin start="2020-02-19 20:40:16.001566088 +0000 UTC
[TRACE] client.alloc_runner.task_runner: skipping done prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=validate
[TRACE] client.alloc_runner.task_runner: running prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=task_dir start="2020-02-19 20:40:16.002243
[TRACE] client.alloc_runner.task_runner: finished prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=task_dir end="2020-02-19 20:40:16.0023614
[DEBUG] worker: dequeued evaluation: eval_id=24649d0e-13c0-e60b-6a9a-3634cd10d8eb
[TRACE] client.alloc_runner.task_runner: running prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=logmon start="2020-02-19 20:40:16.00249705
[DEBUG] worker.service_sched: reconciled current state with desired state: eval_id=24649d0e-13c0-e60b-6a9a-3634cd10d8eb job_id=example namespace=default results="Total c
(place 0) (inplace 0) (destructive 0) (stop 0) (migrate 0) (ignore 1) (canary 0)"
[DEBUG] worker.service_sched: setting eval status: eval_id=24649d0e-13c0-e60b-6a9a-3634cd10d8eb job_id=example namespace=default status=complete
[DEBUG] client: evaluations triggered by node update: num_evals=2
[TRACE] client: next heartbeat: period=18.289356258s
[DEBUG] client: state updated: node_status=ready
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=alloc_dir end="2020-02-19 20:40:16.003089316 +0000 UTC m=+4.183122
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=await_previous_allocations start="2020-02-19 20:40:16.003105382 +00
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=await_previous_allocations end="2020-02-19 20:40:16.00311156 +0000
[DEBUG] client.server_mgr: new server list: new_servers=[10.0.2.15:4647] old_servers=[0.0.0.0:4647, 10.0.2.15:4647]
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=migrate_disk start="2020-02-19 20:40:16.003117447 +0000 UTC m=+4.18
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=migrate_disk end="2020-02-19 20:40:16.003236871 +0000 UTC m=+4.183
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=alloc_health_watcher start="2020-02-19 20:40:16.003243299 +0000 UTC
[TRACE] client.alloc_runner.runner_hook.alloc_health_watcher: not watching; already has health set: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=alloc_health_watcher end="2020-02-19 20:40:16.003252013 +0000 UTC
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=network start="2020-02-19 20:40:16.003256932 +0000 UTC m=+4.1832902
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=network end="2020-02-19 20:40:16.003261616 +0000 UTC m=+4.18329498
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=group_services start="2020-02-19 20:40:16.003266356 +0000 UTC m=+4.
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=group_services end="2020-02-19 20:40:16.003271293 +0000 UTC m=+4.1
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=consul_socket start="2020-02-19 20:40:16.003276112 +0000 UTC m=+4.1
[DEBUG] worker: dequeued evaluation: eval_id=d2b2b595-8bdb-92d2-b197-246fe4bb3275
[TRACE] client.alloc_runner: finished pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=consul_socket end="2020-02-19 20:40:16.004178733 +0000 UTC m=+4.18
[TRACE] client.alloc_runner: running pre-run hook: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 name=csi_hook start="2020-02-19 20:40:16.004493071 +0000 UTC m=+4.184526
[TRACE] client.alloc_runner.task_runner: finished prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=logmon end="2020-02-19 20:40:16.005090195
[TRACE] client.alloc_runner.task_runner: skipping done prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=dispatch_payload
[TRACE] client.alloc_runner.task_runner: running prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=volumes start="2020-02-19 20:40:16.0053261
[TRACE] client.alloc_runner.task_runner: finished prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=volumes end="2020-02-19 20:40:16.00534218
[DEBUG] worker: updated evaluation: eval="<Eval "24649d0e-13c0-e60b-6a9a-3634cd10d8eb" JobID: "example" Namespace: "default">"
[DEBUG] worker: ack evaluation: eval_id=24649d0e-13c0-e60b-6a9a-3634cd10d8eb
[DEBUG] client: allocation updates applied: added=0 removed=0 updated=1 ignored=2 errors=0
[DEBUG] worker.service_sched: reconciled current state with desired state: eval_id=d2b2b595-8bdb-92d2-b197-246fe4bb3275 job_id=csi-something namespace=default results="T
lace 0) (inplace 0) (destructive 0) (stop 0) (migrate 0) (ignore 1) (canary 0)"
[DEBUG] worker.service_sched: setting eval status: eval_id=d2b2b595-8bdb-92d2-b197-246fe4bb3275 job_id=csi-something namespace=default status=complete
[TRACE] client.alloc_runner.task_runner: skipping done prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=artifacts
[TRACE] client.alloc_runner.task_runner: skipping done prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=devices
[TRACE] client.alloc_runner.task_runner: skipping done prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=csi_plugin_supervisor
[TRACE] client.alloc_runner.task_runner: running prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=script_checks start="2020-02-19 20:40:16.0
[TRACE] client.alloc_runner.task_runner: finished prestart hook: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin name=script_checks end="2020-02-19 20:40:16.00
[TRACE] client.alloc_runner.task_runner: finished prestart hooks: alloc_id=992bc62a-b526-d112-759c-87e6ea1f4041 task=plugin end="2020-02-19 20:40:16.005976724 +0000 UTC
[WARN]  client.driver_mgr.docker: RemoveImage on non-referenced counted image id: driver=docker image_id=sha256:87856cc39862cec77541d68382e4867d7ccb29a85a17221446c857dda
[TRACE] client.alloc_runner.task_runner: running stop hooks: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e task=redis start="2020-02-19 20:40:16.014619678 +0000 UTC m=+4
[TRACE] client.alloc_runner.task_runner: running stop hook: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e task=redis name=logmon start="2020-02-19 20:40:16.014661726 +00
[TRACE] client.alloc_runner.task_runner.task_hook: error reattaching to logmon when stopping: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e task=redis error="Reattachmen
[TRACE] client.alloc_runner.task_runner: finished stop hook: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e task=redis name=logmon end="2020-02-19 20:40:16.01476494 +0000
[TRACE] client.alloc_runner.task_runner: running stop hook: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e task=redis name=script_checks start="2020-02-19 20:40:16.014775
[TRACE] client.alloc_runner.task_runner: finished stop hook: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e task=redis name=script_checks end="2020-02-19 20:40:16.0147873
[TRACE] client.alloc_runner.task_runner: finished stop hooks: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e task=redis end="2020-02-19 20:40:16.014794186 +0000 UTC m=+4.
[TRACE] client.alloc_runner: running post-run hooks: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e start="2020-02-19 20:40:16.014806547 +0000 UTC m=+4.194839913"
[TRACE] client.alloc_runner: running post-run hook: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e name=alloc_health_watcher start="2020-02-19 20:40:16.014966677 +0000 UT
[TRACE] client.alloc_runner: finished post-run hooks: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e name=alloc_health_watcher end="2020-02-19 20:40:16.014976799 +0000 UT
[TRACE] client.alloc_runner: running post-run hook: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e name=network start="2020-02-19 20:40:16.015006746 +0000 UTC m=+4.195040
[TRACE] client.alloc_runner: finished post-run hooks: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e name=network end="2020-02-19 20:40:16.015015607 +0000 UTC m=+4.195048
[TRACE] client.alloc_runner: running post-run hook: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e name=group_services start="2020-02-19 20:40:16.01502179 +0000 UTC m=+4.
[TRACE] client.alloc_runner: finished post-run hooks: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e name=group_services end="2020-02-19 20:40:16.015029196 +0000 UTC m=+4
[TRACE] client.alloc_runner: running post-run hook: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e name=consul_socket start="2020-02-19 20:40:16.015035263 +0000 UTC m=+4.
[TRACE] client.alloc_runner: finished post-run hooks: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e name=consul_socket end="2020-02-19 20:40:16.01504153 +0000 UTC m=+4.1
[TRACE] client.alloc_runner: running post-run hook: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e name=csi_hook start="2020-02-19 20:40:16.0150501 +0000 UTC m=+4.1950834
[TRACE] client.alloc_runner: handling task state update: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e done=false
[INFO]  client.gc: marking allocation for GC: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e
[TRACE] client.alloc_runner: sending updated alloc: alloc_id=98c2b555-1a1a-f608-5c91-d7cab9a6328e client_status=failed desired_status=
[DEBUG] http: request complete: method=GET path=/v1/allocations?prefix=8c9b duration=1.028929ms
[DEBUG] consul.sync: sync complete: registered_services=1 deregistered_services=0 registered_checks=1 deregistered_checks=0
[DEBUG] worker: updated evaluation: eval="<Eval "d2b2b595-8bdb-92d2-b197-246fe4bb3275" JobID: "csi-something" Namespace: "default">"
[DEBUG] worker: ack evaluation: eval_id=d2b2b595-8bdb-92d2-b197-246fe4bb3275
[TRACE] client.alloc_runner: finished pre-run hooks: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 end="2020-02-19 20:40:16.022423889 +0000 UTC m=+4.202457331" duration=
[ERROR] client.alloc_runner: prerun failed: alloc_id=8c9b5361-1929-f85b-b305-54f8c6993484 error="pre-run hook "csi_hook" failed: Plugin not found"
@tgross tgross added this to the 0.11.0 milestone Feb 19, 2020
@tgross tgross self-assigned this Mar 9, 2020
@tgross
Copy link
Member Author

tgross commented Mar 10, 2020

I've figure out the source this problem (but not yet a solution), and it's related to the delay in plugin fingerprinting discussed in #7296. Here's what the sequence of events looks like:


Client starts back up and does the usual fingerprinting of CPU, memory, etc. Note that our dynamic plugins aren't in the mix here at all. And how could they be? We haven't restored our handles to the allocations that run them.

2020-03-10T17:35:35.976Z [DEBUG] client.plugin: finished plugin manager initial fingerprint: plugin-type=driver

At this point fingerprinting is "complete", but we haven't fingerprinted any CSI plugins! So we start restoring allocs. In the log snippets we'll see below, 0502c2ab is the example app alloc, and ceafe14a is the plugin alloc.

2020-03-10T17:35:35.980Z [TRACE] client.alloc_runner: running pre-run hooks: alloc_id=0502c2ab-b989-d643-a606-cc011a01c099 start="2020-03-10 17:35:35.980599731 +0000 UTC m=+6.166041525"
2020-03-10T17:35:35.980Z [TRACE] client.alloc_runner: running pre-run hooks: alloc_id=ceafe14a-2c42-5ee0-fb23-4955b43ebb50 start="2020-03-10 17:35:35.980815035 +0000 UTC m=+6.166256848"

The example app starts its CSI hook, but we haven't fingerprinted the plugin yet so this isn't going to go well...

2020-03-10T17:35:35.987Z [TRACE] client.alloc_runner: running pre-run hook: alloc_id=0502c2ab-b989-d643-a606-cc011a01c099 name=csi_hook start="2020-03-10 17:35:35.987929175 +0000 UTC m=+6.173370970"

We continue merrily along restoring allocs and firing their prestart hooks. We reach the plugin supervisor prestart hook, which we've already done so we skip it. Is that right? At first I thought this might be the place to fix the problem but it'd be racy with other jobs on the same client.

2020-03-10T17:35:35.990Z [TRACE] client.alloc_runner.task_runner: skipping done prestart hook: alloc_id=ceafe14a-2c42-5ee0-fb23-4955b43ebb50 task=plugin name=csi_plugin_supervisor

Our example app's CSI hook has finally hit the server and... uh oh, we're trying to re-claim the volume but the server doesn't know that our plugin on the client is healthy yet. Should we be re-claiming it? That doesn't quite make sense either, especially given we don't have heartyeet / #2185 yet.

2020-03-10T17:35:35.992Z [ERROR] nomad.fsm: CSIVolumeClaim failed: error="volume max claim reached"

We go on to run the plugin's poststart hooks, including the poststart for the plugin supervisor.

2020-03-10T17:35:35.992Z [TRACE] client.alloc_runner.task_runner: finished poststart hooks: alloc_id=ceafe14a-2c42-5ee0-fb23-4955b43ebb50 task=plugin name=csi_plugin_supervisor end="2020-03-10 17:35:35.992785449 +0000 UTC m=+6.178227246" duration=19.306µs

Finally the example apps CSI hook gets a message back from server "volume max claim reached", and because the plugin hasn't been fingerprinted we're going to call this a failure and mark the example app alloc for termination.

2020-03-10T17:35:35.992Z [ERROR] client.rpc: error performing RPC to server: error="rpc error: volume max claim reached" rpc=CSIVolume.Claim server=0.0.0.0:4647
2020-03-10T17:35:35.992Z [TRACE] client.alloc_runner: finished pre-run hooks: alloc_id=0502c2ab-b989-d643-a606-cc011a01c099 end="2020-03-10 17:35:35.99280877 +0000 UTC m=+6.178250566" duration=12.209041ms
2020-03-10T17:35:35.992Z [ERROR] client.alloc_runner: prerun failed: alloc_id=0502c2ab-b989-d643-a606-cc011a01c099 error="pre-run hook "csi_hook" failed: claim volumes: rpc error: volume max claim reached"

Ok, well this example task failed, so we run its stop hooks...

2020-03-10T17:35:35.994Z [TRACE] client.alloc_runner.task_runner: setting task state: alloc_id=0502c2ab-b989-d643-a606-cc011a01c099 task=redis state=dead event="Setup Failure"
2020-03-10T17:35:35.996Z [TRACE] client.alloc_runner.task_runner: running stop hooks: alloc_id=0502c2ab-b989-d643-a606-cc011a01c099 task=redis start="2020-03-10 17:35:35.996037409 +0000 UTC m=+6.181479228"
2020-03-10T17:35:35.996Z [TRACE] client.alloc_runner.task_runner: running stop hook: alloc_id=0502c2ab-b989-d643-a606-cc011a01c099 task=redis name=logmon start="2020-03-10 17:35:35.99605562 +0000 UTC m=+6.181497416"
2020-03-10T17:35:35.996Z [TRACE] client.alloc_runner: handling task state update: alloc_id=0502c2ab-b989-d643-a606-cc011a01c099 done=false
2020-03-10T17:35:35.996Z [INFO]  client.gc: marking allocation for GC: alloc_id=0502c2ab-b989-d643-a606-cc011a01c099
2020-03-10T17:35:35.996Z [TRACE] client.alloc_runner: sending updated alloc: alloc_id=0502c2ab-b989-d643-a606-cc011a01c099 client_status=failed desired_status=

The plugin supervisor loop probes the plugin, but until the dynamic plugin manager does the capabilities check it isn't considered healthy for use:

2020-03-10T17:35:35.996Z [TRACE] client.alloc_runner.task_runner.task_hook.csi_client: finished client unary call: alloc_id=ceafe14a-2c42-5ee0-fb23-4955b43ebb50 plugin.name=hostpath-plugin0 plugin.type=monolith task=plugin grpc.code=OK duration=3.897287ms grpc.service=csi.v1.Identity grpc.method=Probe
2020-03-10T17:35:35.999Z [TRACE] client.alloc_runner: handling task state update: alloc_id=ceafe14a-2c42-5ee0-fb23-4955b43ebb50 done=false
2020-03-10T17:35:35.999Z [TRACE] client.alloc_runner: sending updated alloc: alloc_id=ceafe14a-2c42-5ee0-fb23-4955b43ebb50 client_status=running desired_status=
2020-03-10T17:35:36.001Z [TRACE] client.alloc_runner.task_runner.task_hook.csi_client: finished client unary call: alloc_id=ceafe14a-2c42-5ee0-fb23-4955b43ebb50 plugin.name=hostpath-plugin0 plugin.type=monolith task=plugin grpc.code=OK duration=1.318428ms grpc.service=csi.v1.Identity grpc.method=GetPluginInfo
2020-03-10T17:35:36.002Z [TRACE] client.alloc_runner.task_runner.task_hook.csi_client: finished client unary call: alloc_id=ceafe14a-2c42-5ee0-fb23-4955b43ebb50 plugin.name=hostpath-plugin0 plugin.type=monolith task=plugin grpc.code=OK duration=1.634072ms grpc.service=csi.v1.Identity grpc.method=Probe

Meanwhile, server is cleaning up the old claim and rescheduling the example app:

2020-03-10T17:35:36.234Z [DEBUG] nomad.client: adding evaluations for rescheduling failed allocations: num_evals=2
2020-03-10T17:35:36.238Z [DEBUG] worker: dequeued evaluation: eval_id=d0e40b0c-e60c-b746-e2b2-93b4c833f119
2020-03-10T17:35:36.238Z [TRACE] core.sched: garbage collecting unclaimed CSI volume claims
2020-03-10T17:35:36.238Z [TRACE] core.sched: garbage collecting unclaimed CSI volume claims for job: job=example

It takes us a few tries because the plugin still hasn't been fingerprinted. During client-GC, the plugin is "not found" yet (also, what's up with this error message?):

    2020-03-10T17:35:38.997Z [ERROR] client.alloc_runner: postrun failed: alloc_id=0502c2ab-b989-d643-a606-cc011a01c099 error="hook "csi_hook" failed: 1 error occurred:
	* Plugin not found
"

Finally the plugin fingerprinter says "oh hey, there's a plugin on this client!"

2020-03-10T17:36:05.906Z [DEBUG] client: detected new CSI plugin: name=hostpath-plugin0 type=csi-controller
2020-03-10T17:36:05.906Z [DEBUG] client: detected new CSI plugin: name=hostpath-plugin0 type=csi-node
2020-03-10T17:36:05.906Z [DEBUG] client.hostpath-plugin0: Skipping volume manager setup - not managing a Node plugin: type=csi-controller
2020-03-10T17:36:05.912Z [TRACE] client.hostpath-plugin0: finished client unary call: grpc.code=OK duration=5.424501ms grpc.service=csi.v1.Identity grpc.method=GetPluginCapabilities
2020-03-10T17:36:05.912Z [TRACE] client.hostpath-plugin0: finished client unary call: grpc.code=OK duration=5.931927ms grpc.service=csi.v1.Identity grpc.method=GetPluginCapabilities
2020-03-10T17:36:05.915Z [TRACE] client.hostpath-plugin0: finished client unary call: grpc.code=OK duration=2.736905ms grpc.service=csi.v1.Node grpc.method=NodeGetInfo
2020-03-10T17:36:05.916Z [TRACE] client.hostpath-plugin0: finished client unary call: grpc.code=OK duration=3.26227ms grpc.service=csi.v1.Identity grpc.method=Probe
2020-03-10T17:36:05.917Z [TRACE] client.hostpath-plugin0: finished client unary call: grpc.code=OK duration=1.736375ms grpc.service=csi.v1.Identity grpc.method=Probe
2020-03-10T17:36:05.919Z [TRACE] client.hostpath-plugin0: finished client unary call: grpc.code=OK duration=3.784105ms grpc.service=csi.v1.Controller grpc.method=ControllerGetCapabilities
2020-03-10T17:36:05.920Z [TRACE] client.hostpath-plugin0: finished client unary call: grpc.code=OK duration=2.142692ms grpc.service=csi.v1.Node grpc.method=NodeGetCapabilities
2020-03-10T17:36:05.920Z [DEBUG] client.hostpath-plugin0: Setup volume manager
2020-03-10T17:36:05.994Z [DEBUG] worker: dequeued evaluation: eval_id=820dbed0-bfba-4c23-c7a0-afa2f840bf7b

And the scheduler finally catches up with reality on the client and sends it a placement for the alloc:

2020-03-10T17:36:11.066Z [DEBUG] worker.service_sched: reconciled current state with desired state: eval_id=f572c6d9-1e98-3e69-857c-e9c9d5fc6343 job_id=example namespace=default results="Total changes: (place 1) (destructive 0) (inplace 0) (stop 0)
Desired Changes for "cache": (place 1) (inplace 0) (destructive 0) (stop 0) (migrate 0) (ignore 0) (canary 0)"

@tgross
Copy link
Member Author

tgross commented Mar 12, 2020

Will be fixed by #7328 #7330 once both are merged.

@tgross tgross closed this as completed Mar 16, 2020
@github-actions
Copy link

I'm going to lock this issue because it has been closed for 120 days ⏳. This helps our maintainers find and focus on the active issues.
If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Nov 11, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

1 participant