nomad-provider-issue-agent-output

==> Loaded configuration from C:\ProgramData\nomad\conf\client.hcl
==> Starting Nomad agent...
==> Nomad agent configuration:

       Advertise Addrs: HTTP: 10.101.1.1:4646
            Bind Addrs: HTTP: 10.101.1.1:4646
                Client: true
             Log Level: debug
                Region: global (DC: mio)
                Server: false
               Version: 0.11.1

==> Nomad agent started! Log data will stream in below:

    2020-05-17T03:30:00.377Z [WARN]  agent.plugin_loader: skipping external plugins since plugin_dir doesn't exist: plugin_dir=C:\ProgramData\nomad\data\plugins
    2020-05-17T03:30:00.888Z [DEBUG] agent.plugin_loader.docker: using client connection initialized from environment: plugin_dir=C:\ProgramData\nomad\data\plugins
    2020-05-17T03:30:00.918Z [DEBUG] agent.plugin_loader.docker: using client connection initialized from environment: plugin_dir=C:\ProgramData\nomad\data\plugins
    2020-05-17T03:30:00.918Z [INFO]  agent: detected plugin: name=qemu type=driver plugin_version=0.1.0
    2020-05-17T03:30:00.923Z [INFO]  agent: detected plugin: name=java type=driver plugin_version=0.1.0
    2020-05-17T03:30:00.923Z [INFO]  agent: detected plugin: name=docker type=driver plugin_version=0.1.0
    2020-05-17T03:30:00.923Z [INFO]  agent: detected plugin: name=raw_exec type=driver plugin_version=0.1.0
    2020-05-17T03:30:00.923Z [INFO]  agent: detected plugin: name=exec type=driver plugin_version=0.1.0
    2020-05-17T03:30:00.937Z [INFO]  client: using state directory: state_dir=C:\ProgramData\nomad\data\client
    2020-05-17T03:30:00.946Z [INFO]  client: using alloc directory: alloc_dir=C:\ProgramData\nomad\data\alloc
    2020-05-17T03:30:01.114Z [DEBUG] client.fingerprint_mgr: built-in fingerprints: fingerprinters=[arch, consul, cpu, host, memory, network, nomad, signal, storage, vault, env_aws, env_gce]
    2020-05-17T03:30:02.264Z [INFO]  client.fingerprint_mgr.consul: consul agent is available
    2020-05-17T03:30:02.265Z [DEBUG] client.fingerprint_mgr: fingerprinting periodically: fingerprinter=consul period=15s
    2020-05-17T03:30:02.341Z [DEBUG] client.fingerprint_mgr.cpu: detected cpu frequency: MHz=2400
    2020-05-17T03:30:02.341Z [DEBUG] client.fingerprint_mgr.cpu: detected core count: cores=4
    2020-05-17T03:30:19.617Z [DEBUG] client.fingerprint_mgr.network: link speed detected: interface="Ethernet0 2" mbits=10000
    2020-05-17T03:30:19.644Z [DEBUG] client.fingerprint_mgr.network: detected interface IP: interface="Ethernet0 2" IP=10.101.1.1
    2020-05-17T03:30:19.672Z [DEBUG] client.fingerprint_mgr: fingerprinting periodically: fingerprinter=vault period=15s
    2020-05-17T03:30:25.770Z [DEBUG] client.fingerprint_mgr.env_gce: could not read value for attribute: attribute=machine-type error="Get "http://169.254.169.254/computeMetadata/v1/instance/machine-type": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"
    2020-05-17T03:30:25.770Z [DEBUG] client.fingerprint_mgr.env_gce: error querying GCE Metadata URL, skipping
    2020-05-17T03:30:25.770Z [DEBUG] client.fingerprint_mgr: detected fingerprints: node_attrs=[arch, consul, cpu, host, network, nomad, signal, storage]
    2020-05-17T03:30:25.799Z [INFO]  client.plugin: starting plugin manager: plugin-type=csi
    2020-05-17T03:30:25.799Z [INFO]  client.plugin: starting plugin manager: plugin-type=driver
    2020-05-17T03:30:25.819Z [INFO]  client.plugin: starting plugin manager: plugin-type=device
    2020-05-17T03:30:25.819Z [DEBUG] client.device_mgr: exiting since there are no device plugins
    2020-05-17T03:30:25.833Z [DEBUG] client.driver_mgr: initial driver fingerprint: driver=java health=undetected description=
    2020-05-17T03:30:25.835Z [DEBUG] client.driver_mgr: initial driver fingerprint: driver=qemu health=undetected description=
    2020-05-17T03:30:25.851Z [DEBUG] client.plugin: waiting on plugin manager initial fingerprint: plugin-type=driver
    2020-05-17T03:30:25.857Z [DEBUG] client.plugin: waiting on plugin manager initial fingerprint: plugin-type=device
    2020-05-17T03:30:25.857Z [DEBUG] client.plugin: finished plugin manager initial fingerprint: plugin-type=device
    2020-05-17T03:30:25.864Z [DEBUG] client.driver_mgr: initial driver fingerprint: driver=exec health=undetected description="exec driver unsupported on client OS"
    2020-05-17T03:30:25.869Z [DEBUG] client.driver_mgr: initial driver fingerprint: driver=raw_exec health=healthy description=Healthy
    2020-05-17T03:30:26.048Z [DEBUG] client.driver_mgr.docker: could not connect to docker daemon: driver=docker endpoint=npipe:////./pipe/docker_engine error="Get "http://unix.sock/version": open //./pipe/docker_engine: The system cannot find the file specified."
    2020-05-17T03:30:26.048Z [DEBUG] client.driver_mgr: initial driver fingerprint: driver=docker health=undetected description="Failed to connect to docker daemon"
    2020-05-17T03:30:26.048Z [DEBUG] client.driver_mgr: detected drivers: drivers="map[healthy:[raw_exec] undetected:[qemu java exec docker]]"
    2020-05-17T03:30:26.191Z [DEBUG] client.plugin: finished plugin manager initial fingerprint: plugin-type=driver
    2020-05-17T03:30:37.073Z [DEBUG] client.server_mgr: new server list: new_servers=[10.101.2.122:4647] old_servers=[]
    2020-05-17T03:30:37.073Z [INFO]  client: started client: node_id=8b970331-98d0-ebf9-e7aa-a9e9b1ecc768
    2020-05-17T03:30:37.315Z [DEBUG] client: updated allocations: index=3516191 total=0 pulled=0 filtered=0
    2020-05-17T03:30:37.315Z [DEBUG] client: allocation updates: added=0 removed=0 updated=0 ignored=0
    2020-05-17T03:30:37.315Z [DEBUG] client: allocation updates applied: added=0 removed=0 updated=0 ignored=0 errors=0
    2020-05-17T03:30:37.518Z [INFO]  client: node registration complete
    2020-05-17T03:30:37.937Z [DEBUG] consul.sync: sync complete: registered_services=1 deregistered_services=0 registered_checks=1 deregistered_checks=0
    2020-05-17T03:30:39.480Z [DEBUG] client: state updated: node_status=ready
 === redacted ===
    2020-05-19T16:31:05.945Z [DEBUG] http: request complete: method=GET path=/v1/metrics?format=prometheus duration=2.0032ms
    2020-05-19T16:31:14.036Z [DEBUG] http: request complete: method=GET path=/v1/agent/health?type=client duration=0s
    2020-05-19T16:31:20.943Z [DEBUG] http: request complete: method=GET path=/v1/metrics?format=prometheus duration=997.2µs
    2020-05-19T16:31:24.038Z [DEBUG] http: request complete: method=GET path=/v1/agent/health?type=client duration=0s
    2020-05-19T16:31:34.041Z [DEBUG] http: request complete: method=GET path=/v1/agent/health?type=client duration=0s
    2020-05-19T16:31:35.943Z [DEBUG] http: request complete: method=GET path=/v1/metrics?format=prometheus duration=993.7µs
    2020-05-19T16:31:39.681Z [DEBUG] client: updated allocations: index=3560992 total=1 pulled=1 filtered=0
    2020-05-19T16:31:39.681Z [DEBUG] client: allocation updates: added=1 removed=0 updated=0 ignored=0
    2020-05-19T16:31:39.686Z [DEBUG] client: allocation updates applied: added=1 removed=0 updated=0 ignored=0 errors=0
    2020-05-19T16:31:39.696Z [DEBUG] client.alloc_runner.task_runner.task_hook.logmon: starting plugin: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test path=C:\ProgramData\chocolatey\lib\nomad\tools\nomad.exe args=[C:\ProgramData\chocolatey\lib\nomad\tools\nomad.exe, logmon]
    2020-05-19T16:31:39.697Z [DEBUG] client.alloc_runner.task_runner.task_hook.logmon: plugin started: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test path=C:\ProgramData\chocolatey\lib\nomad\tools\nomad.exe pid=3560
    2020-05-19T16:31:39.697Z [DEBUG] client.alloc_runner.task_runner.task_hook.logmon: waiting for RPC address: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test path=C:\ProgramData\chocolatey\lib\nomad\tools\nomad.exe
    2020-05-19T16:31:39.737Z [DEBUG] client.alloc_runner.task_runner.task_hook.logmon: using plugin: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test version=2
    2020-05-19T16:31:39.737Z [DEBUG] client.alloc_runner.task_runner.task_hook.logmon.nomad.exe: plugin address: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test @module=logmon address=127.0.0.1:10000 network=tcp timestamp=2020-05-19T16:31:39.710Z
    2020-05-19T16:31:39.758Z [INFO]  client.alloc_runner.task_runner.task_hook.logmon.nomad.exe: opening fifo: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test path=//./pipe/test-1bb590c9.stdout @module=logmon timestamp=2020-05-19T16:31:39.758Z
    2020-05-19T16:31:39.759Z [INFO]  client.alloc_runner.task_runner.task_hook.logmon.nomad.exe: opening fifo: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test @module=logmon path=//./pipe/test-1bb590c9.stderr timestamp=2020-05-19T16:31:39.758Z
    2020/05/19 16:31:39.776186 [INFO] (runner) creating new runner (dry: false, once: false)
    2020/05/19 16:31:39.776186 [DEBUG] (runner) final config: {"Consul":{"Address":"127.0.0.1:8500","Auth":{"Enabled":false,"Username":"","Password":""},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"Token":"","Transport":{"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":5,"TLSHandshakeTimeout":10000000000}},"Dedup":{"Enabled":false,"MaxStale":2000000000,"Prefix":"consul-template/dedup/","TTL":15000000000},"Exec":{"Command":"","Enabled":false,"Env":{"Blacklist":[],"Custom":[],"Pristine":false,"Whitelist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":0},"KillSignal":2,"LogLevel":"WARN","MaxStale":2000000000,"PidFile":"","ReloadSignal":1,"Syslog":{"Enabled":false,"Facility":"LOCAL0"},"Templates":[{"Backup":false,"Command":"","CommandTimeout":30000000000,"Contents":"sample\n","CreateDestDirs":true,"Destination":"C:\\ProgramData\\nomad\\data\\alloc\\d219b648-c471-bf43-a0e9-8bd85368ab1b\\test\\sample.csv","ErrMissingKey":false,"Exec":{"Command":"","Enabled":false,"Env":{"Blacklist":[],"Custom":[],"Pristine":false,"Whitelist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":420,"Source":"","Wait":{"Enabled":false,"Min":0,"Max":0},"LeftDelim":"{{","RightDelim":"}}","FunctionBlacklist":["plugin"],"SandboxPath":"C:\\ProgramData\\nomad\\data\\alloc\\d219b648-c471-bf43-a0e9-8bd85368ab1b\\test"}],"Vault":{"Address":"","Enabled":false,"Namespace":"","RenewToken":false,"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":true,"Key":"","ServerName":"","Verify":true},"Transport":{"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":5,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false},"Wait":{"Enabled":false,"Min":0,"Max":0},"Once":false}
    2020/05/19 16:31:39.776186 [INFO] (runner) creating watcher
    2020/05/19 16:31:39.776186 [INFO] (runner) starting
    2020/05/19 16:31:39.776186 [DEBUG] (runner) running initial templates
    2020/05/19 16:31:39.776186 [DEBUG] (runner) initiating run
    2020/05/19 16:31:39.776186 [DEBUG] (runner) checking template 5177a58dc65c8a14dc90c69db3bf3dd2
    2020/05/19 16:31:39.776186 [DEBUG] (runner) rendering "(dynamic)" => "C:\\ProgramData\\nomad\\data\\alloc\\d219b648-c471-bf43-a0e9-8bd85368ab1b\\test\\sample.csv"
    2020/05/19 16:31:39.778190 [INFO] (runner) rendered "(dynamic)" => "C:\\ProgramData\\nomad\\data\\alloc\\d219b648-c471-bf43-a0e9-8bd85368ab1b\\test\\sample.csv"
    2020/05/19 16:31:39.778190 [DEBUG] (runner) diffing and updating dependencies
    2020/05/19 16:31:39.778190 [DEBUG] (runner) watching 0 dependencies
    2020/05/19 16:31:39.778190 [DEBUG] (runner) all templates rendered
    2020-05-19T16:31:39.786Z [INFO]  client.driver_mgr.raw_exec: starting task: driver=raw_exec driver_cfg="{Command:powershell.exe Args:[-NoProfile -ExecutionPolicy Bypass -Command Write-Host Hello]}"
    2020-05-19T16:31:39.787Z [DEBUG] client.driver_mgr.raw_exec.executor: starting plugin: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b driver=raw_exec task_name=test path=C:\ProgramData\chocolatey\lib\nomad\tools\nomad.exe args=[C:\ProgramData\chocolatey\lib\nomad\tools\nomad.exe, executor, {"LogFile":"C:\\ProgramData\\nomad\\data\\alloc\\d219b648-c471-bf43-a0e9-8bd85368ab1b\\test\\executor.out","LogLevel":"debug","FSIsolation":false}]
    2020-05-19T16:31:39.787Z [DEBUG] client.driver_mgr.raw_exec.executor: plugin started: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b driver=raw_exec task_name=test path=C:\ProgramData\chocolatey\lib\nomad\tools\nomad.exe pid=1740
    2020-05-19T16:31:39.787Z [DEBUG] client.driver_mgr.raw_exec.executor: waiting for RPC address: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b driver=raw_exec task_name=test path=C:\ProgramData\chocolatey\lib\nomad\tools\nomad.exe
    2020-05-19T16:31:39.836Z [DEBUG] client: updated allocations: index=3560994 total=1 pulled=0 filtered=1
    2020-05-19T16:31:39.836Z [DEBUG] client: allocation updates: added=0 removed=0 updated=0 ignored=1
    2020-05-19T16:31:39.836Z [DEBUG] client: allocation updates applied: added=0 removed=0 updated=0 ignored=1 errors=0
    2020-05-19T16:31:39.855Z [DEBUG] client.driver_mgr.raw_exec.executor: using plugin: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b driver=raw_exec task_name=test version=2
    2020-05-19T16:31:40.035Z [DEBUG] client: updated allocations: index=3560995 total=1 pulled=0 filtered=1
    2020-05-19T16:31:40.036Z [DEBUG] client: allocation updates: added=0 removed=0 updated=0 ignored=1
    2020-05-19T16:31:40.036Z [DEBUG] client: allocation updates applied: added=0 removed=0 updated=0 ignored=1 errors=0
    2020-05-19T16:31:40.941Z [ERROR] client.driver_mgr.raw_exec: destroying executor failed: driver=raw_exec err="rpc error: code = Unknown desc = executor failed to find process: OpenProcess: The parameter is incorrect."
    2020-05-19T16:31:40.942Z [ERROR] client.driver_mgr.raw_exec: error receiving stream from Stats executor RPC, closing stream: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b driver=raw_exec task_name=test error="rpc error: code = Unavailable desc = transport is closing"
    2020-05-19T16:31:40.942Z [ERROR] client.alloc_runner.task_runner.task_hook.stats_hook: failed to start stats collection for task: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test error="rpc error: code = Canceled desc = grpc: the client connection is closing"
    2020-05-19T16:31:40.951Z [DEBUG] client.driver_mgr.raw_exec.executor: plugin process exited: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b driver=raw_exec task_name=test path=C:\ProgramData\chocolatey\lib\nomad\tools\nomad.exe pid=1740
    2020-05-19T16:31:40.951Z [DEBUG] client.driver_mgr.raw_exec.executor: plugin exited: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b driver=raw_exec task_name=test
    2020-05-19T16:31:40.951Z [INFO]  client.alloc_runner.task_runner: not restarting task: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test reason="Restart unnecessary as task terminated successfully"
    2020-05-19T16:31:40.963Z [INFO]  client.gc: marking allocation for GC: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b
    2020-05-19T16:31:40.973Z [DEBUG] client.alloc_runner.task_runner.task_hook.logmon: plugin process exited: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test path=C:\ProgramData\chocolatey\lib\nomad\tools\nomad.exe pid=3560
    2020-05-19T16:31:40.973Z [DEBUG] client.alloc_runner.task_runner.task_hook.logmon: plugin exited: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test
    2020/05/19 16:31:40.973263 [INFO] (runner) stopping
    2020/05/19 16:31:40.973263 [DEBUG] (runner) stopping watcher
    2020/05/19 16:31:40.973263 [DEBUG] (watcher) stopping all views
    2020-05-19T16:31:40.973Z [DEBUG] client.alloc_runner.task_runner: task run loop exiting: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b task=test
    2020/05/19 16:31:40.973263 [INFO] (runner) received finish
    2020-05-19T16:31:41.036Z [DEBUG] client: updated allocations: index=3560996 total=1 pulled=0 filtered=1
    2020-05-19T16:31:41.036Z [DEBUG] client: allocation updates: added=0 removed=0 updated=0 ignored=1
    2020-05-19T16:31:41.036Z [DEBUG] client: allocation updates applied: added=0 removed=0 updated=0 ignored=1 errors=0
    2020-05-19T16:31:41.235Z [DEBUG] client: updated allocations: index=3560997 total=1 pulled=0 filtered=1
    2020-05-19T16:31:41.235Z [DEBUG] client: allocation updates: added=0 removed=0 updated=0 ignored=1
    2020-05-19T16:31:41.235Z [DEBUG] client: allocation updates applied: added=0 removed=0 updated=0 ignored=1 errors=0
    2020-05-19T16:31:41.768Z [DEBUG] client: updated allocations: index=3560998 total=0 pulled=0 filtered=0
    2020-05-19T16:31:41.768Z [DEBUG] client: allocation updates: added=0 removed=1 updated=0 ignored=0
    2020-05-19T16:31:41.768Z [DEBUG] client: allocation updates applied: added=0 removed=1 updated=0 ignored=0 errors=0
    2020-05-19T16:31:41.768Z [INFO]  client.gc: garbage collecting allocation: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b reason="forced collection"
    2020-05-19T16:31:41.775Z [DEBUG] client.gc: alloc garbage collected: alloc_id=d219b648-c471-bf43-a0e9-8bd85368ab1b
    2020-05-19T16:31:44.042Z [DEBUG] http: request complete: method=GET path=/v1/agent/health?type=client duration=1.0052ms
    2020-05-19T16:31:47.062Z [ERROR] http: request failed: method=GET path=/v1/client/fs/logs/d219b648-c471-bf43-a0e9-8bd85368ab1b?follow=true&offset=50000&origin=end&task=test&type=stdout error="Unknown allocation "d219b648-c471-bf43-a0e9-8bd85368ab1b"" code=404
    2020-05-19T16:31:47.062Z [DEBUG] http: request complete: method=GET path=/v1/client/fs/logs/d219b648-c471-bf43-a0e9-8bd85368ab1b?follow=true&offset=50000&origin=end&task=test&type=stdout duration=55.0038ms
    2020-05-19T16:31:50.943Z [DEBUG] http: request complete: method=GET path=/v1/metrics?format=prometheus duration=999.2µs
    2020-05-19T16:31:54.043Z [DEBUG] http: request complete: method=GET path=/v1/agent/health?type=client duration=0s
    2020-05-19T16:32:04.044Z [DEBUG] http: request complete: method=GET path=/v1/agent/health?type=client duration=0s
    2020-05-19T16:32:05.943Z [DEBUG] http: request complete: method=GET path=/v1/metrics?format=prometheus duration=998µs