herrbpl commented 4 years ago

Describe the bug When you have multiple templates in vault agent config, like:

...
"template" = {
  "source" = "/vault/config/general.json.tpl"
  "destination" = "/vault/secrets/general/general.json"
  "error_on_missing_key"=true    
  "command" = "/bin/sh /vault/config/splitconfig.sh /vault/secrets/general/general.json /vault/secrets/general"
}

# certificates

"template" = {
  "source" = "/vault/config/certificates.json.tpl"
  "destination" = "/vault/secrets/certificates/certificates.json"
  "error_on_missing_key"=true
  "command" = "/bin/sh /vault/config/splitconfig.sh /vault/secrets/certificates/certificates.json /vault/secrets/certificates"
}

# Service credentials

"template" = {
  "source" = "/vault/config/credentials.json.tpl"
  "destination" = "/vault/secrets/credentials/credentials.json"
  "error_on_missing_key"=true
  "command" = "/bin/sh /vault/config/splitconfig.sh /vault/secrets/credentials/credentials.json /vault/secrets/credentials"
}
...

then when agent is run and has rendered all the templates, it does not execute all commands but exits instead after last render has been completed, executing only one or two first commands.

To Reproduce Steps to reproduce the behavior:

Create vault agent config where multiple templates are rendered and each template has command specified as in example, I have kubernetes role auth but use whatever method you like: config-init.hcl


"auto_auth" = {
"method" = {
"mount_path"= "auth/kubernetes"
"config"= {
  "role"= "service-role"
}        
"type" = "kubernetes"
}

"sink" = {
"config" = {
  "path" = "/home/vault/.token"
}

"type" = "file"
}
}

"exit_after_auth" = true "pid_file" = "/home/vault/.pid"

general config

"template" = { "source" = "/vault/config/general.json.tpl" "destination" = "/vault/secrets/general/general.json" "error_on_missing_key"=true
"command" = "/bin/sh /vault/config/splitconfig.sh /vault/secrets/general/general.json /vault/secrets/general" }

certificates

"template" = { "source" = "/vault/config/certificates.json.tpl" "destination" = "/vault/secrets/certificates/certificates.json" "error_on_missing_key"=true "command" = "/bin/sh /vault/config/splitconfig.sh /vault/secrets/certificates/certificates.json /vault/secrets/certificates" }

Service credentials

"template" = { "source" = "/vault/config/credentials.json.tpl" "destination" = "/vault/secrets/credentials/credentials.json" "error_on_missing_key"=true "command" = "/bin/sh /vault/config/splitconfig.sh /vault/secrets/credentials/credentials.json /vault/secrets/credentials" }

"vault" = { "address" = "https://your_vault_instance:port"
}

2. Run 
```bash
vault agent -config ./config-init.hcl

Only some commands get executed, it seems to depend on how fast rendering engine stops.


/ # vault agent -config ./config-init.hcl 
==> Vault server started! Log data will stream in below:

==> Vault agent configuration:

                 Cgo: disabled
           Log Level: info
             Version: Vault v1.3.4

2020-04-08T09:10:28.606Z [INFO] sink.file: creating file sink 2020-04-08T09:10:28.606Z [INFO] sink.file: file sink configured: path=/home/vault/.token2 mode=-rw-r----- 2020-04-08T09:10:28.607Z [INFO] auth.handler: starting auth handler 2020-04-08T09:10:28.607Z [INFO] auth.handler: authenticating 2020-04-08T09:10:28.607Z [INFO] template.server: starting template server 2020/04/08 09:10:28.608191 [INFO] (runner) creating new runner (dry: false, once: false) 2020-04-08T09:10:28.608Z [INFO] sink.server: starting sink server 2020/04/08 09:10:28.608835 [INFO] (runner) creating watcher 2020-04-08T09:10:28.820Z [INFO] auth.handler: authentication successful, sending token to sinks 2020-04-08T09:10:28.820Z [INFO] auth.handler: starting renewal process 2020-04-08T09:10:28.821Z [INFO] sink.file: token written: path=/home/vault/.token2 2020-04-08T09:10:28.821Z [INFO] sink.server: sink server stopped 2020-04-08T09:10:28.821Z [INFO] sinks finished, exiting 2020-04-08T09:10:28.821Z [INFO] template.server: template server received new token 2020/04/08 09:10:28.821278 [INFO] (runner) stopping 2020/04/08 09:10:28.821408 [INFO] (runner) creating new runner (dry: false, once: false) 2020/04/08 09:10:28.821663 [INFO] (runner) creating watcher 2020/04/08 09:10:28.821870 [INFO] (runner) starting 2020-04-08T09:10:28.837Z [INFO] auth.handler: renewed auth token 2020/04/08 09:10:28.937937 [INFO] (runner) rendered "/vault/config/general.json.tpl" => "/vault/secrets/general/general.json" 2020/04/08 09:10:28.938809 [INFO] (runner) executing command "/bin/sh /vault/config/splitconfig.sh /vault/secrets/general/general.json /vault/secrets/general" from "/vault/config/general.json.tpl" => "/vault/secrets/general/general.json" 2020/04/08 09:10:28.938872 [INFO] (child) spawning: /bin/sh /vault/config/splitconfig.sh /vault/secrets/general/general.json /vault/secrets/general 2020/04/08 09:10:29.414758 [INFO] (runner) rendered "/vault/config/certificates.json.tpl" => "/vault/secrets/certificates/certificates.json" 2020/04/08 09:10:29.415439 [INFO] (runner) rendered "/vault/config/credentials.json.tpl" => "/vault/secrets/credentials/credentials.json" 2020/04/08 09:10:29.415507 [INFO] (runner) executing command "/bin/sh /vault/config/splitconfig.sh /vault/secrets/certificates/certificates.json /vault/secrets/certificates" from "/vault/config/certificates.json.tpl" => "/vault/secrets/certificates/certificates.json" 2020/04/08 09:10:29.415569 [INFO] (child) spawning: /bin/sh /vault/config/splitconfig.sh /vault/secrets/certificates/certificates.json /vault/secrets/certificates 2020/04/08 09:10:29.415677 [INFO] (runner) stopping 2020-04-08T09:10:29.415Z [INFO] template.server: template server stopped

Only two of three commands are executed (for general and certificates paths in this example).

**Expected behavior**
There should be THREE execution of command, however, there is only two before agent stops and exits. 

**Environment:**
* Vault CLI Version (retrieve with `vault version`): Vault v1.3.4
* Server Operating System/Architecture: alpine based vault docker hub image running on Kubernetes 1.17.6

**Additional information:**:
content of `/vault/config/splitconfig.sh`
```bash
#!/bin/sh
set +e
[ -z "$(which jq)" ] && apk add jq -q ;
sourcefile=$1
targetdir=$2
for i in $(cat "$sourcefile"  | jq -r 'keys |@tsv') ; do 
  targetfile=$targetdir/$i
  if [ "$targetfile" != "$sourcefile" ]; then
    cat "$sourcefile" | jq --arg a "$i" -r '.[$a]' > "$targetfile";     
  fi
done
exit 0

herrbpl commented 4 years ago

Looks like problem is with multiple passing over template. This is content of credentials template.

/ # cat /vault/config/credentials.json.tpl

{
  {{ scratch.Set "comma" "" }}
  {{ range secrets "secret/development/metadata/test-helm-tbs/paymentgateway-service/credentials" }}
  {{ scratch.Get "comma" }}
  "{{ . }}": 
      {{ with secret (printf "secret/development/test-helm-tbs/paymentgateway-service/credentials/%s" .)  }}{{ toJSONPretty .Data.data }}{{ end }}{{ scratch.Set "comma" "," }}
  {{ end }}
}

As a workaround, I added extra template for rendering:

# Workaround to vault bug

  "template" = {
    "source" = "/vault/config/credentials.json.tpl"
    "destination" = "/tmp/workaround.json"
    "error_on_missing_key"=true
    "wait" = "10s"
    "command" = "/bin/sh -c 'sleep 25'"
  }

This seems to trigger command.

herrbpl commented 4 years ago

It didn't seem to solve the issue. Looks like some optimization is running command per source file and not per target file. If I have one source template file which is rendered to two different targets then only one of target gets rendered and only one command gets executed, not both, even if i delete one target file, it will not be re-rendered by agent.

tyrannosaurus-becks commented 4 years ago

Hi! Thanks for posting this issue.

I dug through our templating code to see if we supported multiple templates, and it looks like we do. We have some test coverage on it where we parse this template, which includes multiple values, and then check to make sure we receive what we expect. To check through what you're seeing, to the second template shown I added a new command = "buzz" line, then added a check for it to this test. The test succeeded, indicating that in some situations it's possible to get the command through.

Would you be willing to convert your config to HCL, and model off that example template more to see if it resolves the issue for you? Thank you!

herrbpl commented 4 years ago

NB! Problem only happens with templates, which have such loop to get first secrets and then contents as in following template

cat credentials.json.tpl:

{
  {{ scratch.Set "comma" "" }}
  {{ range secrets "secret/development/metadata/test-helm-tbs/paymentgateway-service/credentials" }}
  {{ scratch.Get "comma" }}
  "{{ . }}": 
      {{ with secret (printf "secret/development/test-helm-tbs/paymentgateway-service/credentials/%s" .)  }}{{ toJSONPretty .Data.data }}{{ end }}{{ scratch.Set "comma" "," }}
  {{ end }}
}

And it seems to happen only when vault runs only once (exit_after_auth = true) or on first iteration (when exit_after_auth = false) - like it runs command before it has really rendered template fully, it runs already on first pass!

But since output does not contain output yet, command processes empty file and appears not to working.

When vault has been running and has populated dependency tree, then command appears to work - but it really uses results of previous run.

Regular templates which retrieve only secret, seem to run without issues. Converted to HCL format as suggested, result is same. Configuration and logs follow: cat config.hcl:

auto_auth  {
  method  {
    mount_path = "auth/dev-k8s-02"
    config  {
      role = "test-helm-tbs-paymentgateway-service"
    }        
    type = "kubernetes"
  }

  sink {
    config  {
      "path" = "/home/vault/.token"
    }

    type = "file"
  }
}

exit_after_auth = false
pid_file = "/home/vault/.pid"

# general config

template  {
  source = "/vault/config/general.json.tpl"
  destination = "/vault/secrets/general/general.json"
  error_on_missing_key = true    
  command = "/bin/sh /vault/config/splitconfig.sh /vault/secrets/general/general.json /vault/secrets/general"
}

# certificates

template {
  source = "/vault/config/certificates.json.tpl"
  destination = "/vault/secrets/certificates/certificates.json"
  error_on_missing_key = true
  command = "/bin/sh /vault/config/splitconfig.sh /vault/secrets/certificates/certificates.json /vault/secrets/certificates true"
}

# Service credentials

template {
  source = "/vault/config/credentials.json.tpl"
  destination = "/vault/secrets/credentials/credentials.json"
  error_on_missing_key = true
  command = "/bin/sh /vault/config/splitconfig.sh /vault/secrets/credentials/credentials.json /vault/secrets/credentials"
}

vault = {
  address = "https://my.vault.address:port"      
}

log:

==> Vault agent configuration:
Cgo: disabled
Log Level: info
Version: Vault v1.3.4
2020-04-09T07:20:20.030Z [INFO] sink.file: creating file sink
2020-04-09T07:20:20.031Z [INFO] sink.file: file sink configured: path=/home/vault/.token mode=-rw-r-----
2020-04-09T07:20:20.031Z [INFO] auth.handler: starting auth handler
2020-04-09T07:20:20.031Z [INFO] auth.handler: authenticating
2020-04-09T07:20:20.032Z [INFO] sink.server: starting sink server
2020-04-09T07:20:20.032Z [INFO] template.server: starting template server
2020/04/09 07:20:20.032883 [INFO] (runner) creating new runner (dry: false, once: false)
2020/04/09 07:20:20.033394 [INFO] (runner) creating watcher
2020-04-09T07:20:20.215Z [INFO] auth.handler: authentication successful, sending token to sinks
2020-04-09T07:20:20.215Z [INFO] auth.handler: starting renewal process
2020-04-09T07:20:20.216Z [INFO] sink.file: token written: path=/home/vault/.token
2020-04-09T07:20:20.216Z [INFO] sink.server: sink server stopped
2020-04-09T07:20:20.216Z [INFO] sinks finished, exiting
2020-04-09T07:20:20.216Z [INFO] template.server: template server received new token
2020/04/09 07:20:20.216039 [INFO] (runner) stopping
2020/04/09 07:20:20.216069 [INFO] (runner) creating new runner (dry: false, once: false)
2020/04/09 07:20:20.216214 [INFO] (runner) creating watcher
2020/04/09 07:20:20.216336 [INFO] (runner) starting
2020-04-09T07:20:20.228Z [INFO] auth.handler: renewed auth token
2020/04/09 07:20:20.333464 [INFO] (runner) rendered "/vault/config/general.json.tpl" => "/vault/secrets/general/general.json"
2020/04/09 07:20:20.333975 [INFO] (runner) executing command "/bin/sh /vault/config/splitconfig.sh /vault/secrets/general/general.json /vault/secrets/general" from "/vault/config/general.json.tpl" => "/vault/secrets/general/general.json"
2020/04/09 07:20:20.334033 [INFO] (child) spawning: /bin/sh /vault/config/splitconfig.sh /vault/secrets/general/general.json /vault/secrets/general
2020/04/09 07:20:21.058773 [INFO] (runner) rendered "/vault/config/certificates.json.tpl" => "/vault/secrets/certificates/certificates.json"
2020/04/09 07:20:21.059024 [INFO] (runner) executing command "/bin/sh /vault/config/splitconfig.sh /vault/secrets/certificates/certificates.json /vault/secrets/certificates true" from "/vault/config/certificates.json.tpl" => "/vault/secrets/certificates/certificates.json"
2020/04/09 07:20:21.059077 [INFO] (child) spawning: /bin/sh /vault/config/splitconfig.sh /vault/secrets/certificates/certificates.json /vault/secrets/certificates true
2020/04/09 07:20:21.453857 [INFO] (runner) rendered "/vault/config/credentials.json.tpl" => "/vault/secrets/credentials/credentials.json"
2020/04/09 07:20:21.453903 [INFO] (runner) executing command "/bin/sh /vault/config/splitconfig.sh /vault/secrets/credentials/credentials.json /vault/secrets/credentials" from "/vault/config/credentials.json.tpl" => "/vault/secrets/credentials/credentials.json"
2020/04/09 07:20:21.453954 [INFO] (child) spawning: /bin/sh /vault/config/splitconfig.sh /vault/secrets/credentials/credentials.json /vault/secrets/credentials
2020/04/09 07:20:21.454148 [INFO] (runner) stopping
2020-04-09T07:20:21.454Z [INFO] template.server: template server stopped

It runs now three instances of command. But end result is still wrong as command is run before template with loop is fully rendered.

herrbpl commented 4 years ago

I added copying of rendered outputfile contents to backup location as first task of command.

cat /vault/config/splitconfig.sh:

#!/bin/sh -x
LOGDATE=$(date +%Y%m%dT%H%M%S)
set +e
[ -z "$(which jq)" ] && apk add jq -q ;
sourcefile="$1"
targetdir="$2"
echo $LOGDATE >> $targetdir/splitting.log
echo "$1 $2 $3" >> $targetdir/splitting.log
ls -la $targetdir >> $targetdir/splitting.log
logfile="$targetdir/$(basename $sourcefile)-$LOGDATE"
cp "$sourcefile" "$logfile"

certmode="$3"  
for i in $(cat "$sourcefile"  | jq -r 'keys |@tsv') ; do     
if [ "$certmode" == "true" ]; then
    certkeys=$(cat "$sourcefile" | jq --arg a "$i" -r '.[$a] | keys | @tsv')
    for j in $certkeys; do
    targetfile="$targetdir/${i}_${j}"
    [ -f "$targetfile" ] && rm "$targetfile"  
    cat "$sourcefile" | jq --arg a "$i" --arg b "$j" -r '.[$a][$b]' > "$targetfile";     
    done
else
    targetfile=$targetdir/$i    
    if [ "$targetfile" != "$sourcefile" ]; then
    [ -f "$targetfile" ] && rm "$targetfile"               
    cat "$sourcefile" | jq --arg a "$i" -r '.[$a]' > "$targetfile";     
    fi
fi
done
exit 0

From three templates, 100% copied were only teplates without "secrets" loop in them, other copies of files showed up inconsitantly which indicates that command is not actually executing. Missing were mostly ones that by vault log got executed last.

This is log of vault agent running with exit after auth

...
2020/04/09 08:06:12.206892 [INFO] (runner) rendered "/vault/config/general.json.tpl" => "/vault/secrets/general/general.json"
2020/04/09 08:06:12.206925 [INFO] (runner) executing command "/bin/sh /vault/config/splitconfig.sh /vault/secrets/general/general.json /vault/secrets/general" from "/vault/config/general.json.tpl" => "/vault/secrets/general/general.json"
2020/04/09 08:06:12.206983 [INFO] (child) spawning: /bin/sh /vault/config/splitconfig.sh /vault/secrets/general/general.json /vault/secrets/general
2020/04/09 08:06:13.088260 [INFO] (runner) rendered "/vault/config/certificates.json.tpl" => "/vault/secrets/certificates/certificates.json"
2020/04/09 08:06:13.090141 [INFO] (runner) executing command "/bin/sh /vault/config/splitconfig.sh /vault/secrets/certificates/certificates.json /vault/secrets/certificates true" from "/vault/config/certificates.json.tpl" => "/vault/secrets/certificates/certificates.json"
2020/04/09 08:06:13.090204 [INFO] (child) spawning: /bin/sh /vault/config/splitconfig.sh /vault/secrets/certificates/certificates.json /vault/secrets/certificates true
2020/04/09 08:06:13.475428 [INFO] (runner) rendered "/vault/config/credentials.json.tpl" => "/vault/secrets/credentials/credentials.json"
2020/04/09 08:06:13.476189 [INFO] (runner) executing command "/bin/sh /vault/config/splitconfig.sh /vault/secrets/credentials/credentials.json /vault/secrets/credentials" from "/vault/config/credentials.json.tpl" => "/vault/secrets/credentials/credentials.json"
2020/04/09 08:06:13.476253 [INFO] (child) spawning: /bin/sh /vault/config/splitconfig.sh /vault/secrets/credentials/credentials.json /vault/secrets/credentials
2020/04/09 08:06:13.476396 [INFO] (runner) stopping
2020-04-09T08:06:13.476Z [INFO] template.server: template server stopped

And this is output of resulting files after all commands were run:

/ # ls -la /vault/secrets/*/*
-rw-r--r--    1 root     root          5839 Apr  9 08:06 /vault/secrets/certificates/certificates.json
-rw-r--r--    1 root     root          5839 Apr  9 08:06 /vault/secrets/certificates/certificates.json-20200409T080613
-rw-r--r--    1 root     root          5644 Apr  9 08:06 /vault/secrets/certificates/sc_webmoney_cacert.pem
-rw-r--r--    1 root     root             4 Apr  9 08:06 /vault/secrets/certificates/sc_webmoney_clcert.pem
-rw-r--r--    1 root     root             4 Apr  9 08:06 /vault/secrets/certificates/sc_webmoney_key.pem
-rw-r--r--    1 root     root           369 Apr  9 08:06 /vault/secrets/certificates/splitting.log
-rw-r--r--    1 root     root           592 Apr  9 08:06 /vault/secrets/credentials/credentials.json
-rw-r--r--    1 root     root          1050 Apr  9 08:06 /vault/secrets/general/conf_app.json
-rw-r--r--    1 root     root           653 Apr  9 08:06 /vault/secrets/general/conf_db.json
-rw-r--r--    1 root     root           257 Apr  9 08:06 /vault/secrets/general/conf_email.json
-rw-r--r--    1 root     root           173 Apr  9 08:06 /vault/secrets/general/conf_rabbit.json
-rw-r--r--    1 root     root           429 Apr  9 08:06 /vault/secrets/general/conf_routes.json
-rw-r--r--    1 root     root          2912 Apr  9 08:06 /vault/secrets/general/general.json
-rw-r--r--    1 root     root          2912 Apr  9 08:06 /vault/secrets/general/general.json-20200409T080612
-rw-r--r--    1 root     root           345 Apr  9 08:06 /vault/secrets/general/splitting.log

As seen, credentials.json is generated from template but command is not run - no output from command or copy of file that should be there.

Ergo, command running is not working as it should for multi-pass templates.

tyrannosaurus-becks commented 4 years ago

:+1: gotcha. Thank you so much for all these steps to reproduce, very helpful!

hashicorp / vault

Vault agent template does not execute command for all templates #8697

general config

certificates

Service credentials