search

saltstack / salt

Software to automate the management and configuration of any infrastructure or application at scale. Get access to the Salt software package repository here:
https://repo.saltproject.io/
Apache License 2.0
14.16k stars 5.48k forks source link

archive.extracted fails when called against multiple minions, but not against single ones. #47477

Closed devinnasar closed 5 years ago

devinnasar commented 6 years ago

Description of Issue/Question

I'm installing a program to /opt/ from a tar archive which I have staged on s3. Periodically, archive.extracted states based on this archive fail when I target multiple minions, but not when I target them individually.

Setup

State:

{% from "mycompany/map.jinja" import mycompany with context %}
{% set otcli = mycompany.otcli %}

{% set otcli_install_path =  otcli.install_root ~ "/otcli" %}

otcli_clear_installation:
  file.absent:
    - name: {{ otcli_install_path }}

otcli_extracted:
  archive.extracted:
    - name: {{ otcli.install_root }}/
    - source: salt://mycompany/otcli/otcli-{{ otcli.version }}.tar
    - archive_format: tar
    - user: {{ otcli.user }}
    - group: {{ otcli.group }}

otcli_rename_extract_path:
  file.rename:
    - name: {{ otcli_install_path }}
    - source: {{ otcli.install_root }}/otcli-{{ otcli.version }}
    - force: True
    - makedirs: True
    - require:
      - archive: otcli_extracted

{% set otcli_executable = otcli_install_path ~ '/bin/otcli' %}

otcli_executable_exists:
  file.exists:
    - name: {{ otcli_executable }}
    - require:
      - file: otcli_rename_extract_path

otcli_symlink_establlished:
  file.symlink:
    - name: /usr/sbin/otcli
    - target: {{ otcli_executable }}
    - user: {{ otcli.user }}
    - group: {{ otcli.group }}
    - require:
      - file: otcli_executable_exists

Steps to Reproduce Issue

(Include debug logs if possible and relevant.)

Targeting multiple minions (unsuccessful, note how few files are extracted):

[root@OTCMVM0001 dnasar]# salt -C '*QAAP*00 or *DVAP*' state.apply mycompany.otcli
 salt -C '*QAAP*00 or *DVAP*' state.apply mycompany.otcli
OTDVAPVMXXXA:
----------
          ID: otcli_clear_installation
    Function: file.absent
        Name: /opt/otcli
      Result: True
     Comment: Removed directory /opt/otcli
     Started: 13:45:53.164641
    Duration: 6.027 ms
     Changes:   
              ----------
              removed:
                  /opt/otcli
----------
          ID: otcli_extracted
    Function: archive.extracted
        Name: /opt/
      Result: True
     Comment: salt://mycompany/otcli/otcli-1.1-TEST.tar extracted to /opt/, due to absence of one or more files/dirs
     Started: 13:45:53.171333
    Duration: 57677.333 ms
     Changes:   
              ----------
              extracted_files:
                  - otcli-1.1-TEST
                  - otcli-1.1-TEST/lib
                  - otcli-1.1-TEST/lib/otcli-1.1-TEST.jar
                  - otcli-1.1-TEST/lib/kotlin-stdlib-jdk8-1.2.10.jar
                  - otcli-1.1-TEST/lib/kotlinx-coroutines-core-0.21.2.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-cloudfront-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ecs-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ecr-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ec2-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-rds-1.11.257.jar
----------
          ID: otcli_rename_extract_path
    Function: file.rename
        Name: /opt/otcli
      Result: True
     Comment: Moved "/opt/otcli-1.1-TEST" to "/opt/otcli"
     Started: 13:46:50.849274
    Duration: 0.56 ms
     Changes:   
              ----------
              /opt/otcli:
                  /opt/otcli-1.1-TEST
----------
          ID: otcli_executable_exists
    Function: file.exists
        Name: /opt/otcli/bin/otcli
      Result: False
     Comment: Specified path /opt/otcli/bin/otcli does not exist
     Started: 13:46:50.850186
    Duration: 0.376 ms
     Changes:   
----------
          ID: otcli_symlink_establlished
    Function: file.symlink
        Name: /usr/sbin/otcli
      Result: False
     Comment: One or more requisite failed: mycompany.otcli.otcli_executable_exists
     Changes:   

Summary for OTDVAPVMXXXA
------------
Succeeded: 3 (changed=3)
Failed:    2
------------
Total states run:     5
Total run time:  57.684 s
OTQAAPVM0000:
----------
          ID: otcli_clear_installation
    Function: file.absent
        Name: /opt/otcli
      Result: True
     Comment: Removed directory /opt/otcli
     Started: 13:45:53.084957
    Duration: 12.016 ms
     Changes:   
              ----------
              removed:
                  /opt/otcli
----------
          ID: otcli_extracted
    Function: archive.extracted
        Name: /opt/
      Result: True
     Comment: salt://mycompany/otcli/otcli-1.1-TEST.tar extracted to /opt/, due to absence of one or more files/dirs
     Started: 13:45:53.097724
    Duration: 57990.745 ms
     Changes:   
              ----------
              extracted_files:
                  - otcli-1.1-TEST
                  - otcli-1.1-TEST/lib
                  - otcli-1.1-TEST/lib/otcli-1.1-TEST.jar
                  - otcli-1.1-TEST/lib/kotlin-stdlib-jdk8-1.2.10.jar
                  - otcli-1.1-TEST/lib/kotlinx-coroutines-core-0.21.2.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-cloudfront-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ecs-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ecr-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ec2-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-rds-1.11.257.jar
----------
          ID: otcli_rename_extract_path
    Function: file.rename
        Name: /opt/otcli
      Result: True
     Comment: Moved "/opt/otcli-1.1-TEST" to "/opt/otcli"
     Started: 13:46:51.088825
    Duration: 0.526 ms
     Changes:   
              ----------
              /opt/otcli:
                  /opt/otcli-1.1-TEST
----------
          ID: otcli_executable_exists
    Function: file.exists
        Name: /opt/otcli/bin/otcli
      Result: False
     Comment: Specified path /opt/oERROR: Minions returned with non-zero exit code
tcli/bin/otcli does not exist
     Started: 13:46:51.089703
    Duration: 0.393 ms
     Changes:   
----------
          ID: otcli_symlink_establlished
    Function: file.symlink
        Name: /usr/sbin/otcli
      Result: False
     Comment: One or more requisite failed: mycompany.otcli.otcli_executable_exists
     Changes:   

Summary for OTQAAPVM0000
------------
Succeeded: 3 (changed=3)
Failed:    2
------------
Total states run:     5
Total run time:  58.004 s
OTDVAPVMXXXX:
----------
          ID: otcli_clear_installation
    Function: file.absent
        Name: /opt/otcli
      Result: True
     Comment: Removed directory /opt/otcli
     Started: 13:45:53.058306
    Duration: 12.293 ms
     Changes:   
              ----------
              removed:
                  /opt/otcli
----------
          ID: otcli_extracted
    Function: archive.extracted
        Name: /opt/
      Result: True
     Comment: salt://mycompany/otcli/otcli-1.1-TEST.tar extracted to /opt/, due to absence of one or more files/dirs
     Started: 13:45:53.071371
    Duration: 58116.275 ms
     Changes:   
              ----------
              extracted_files:
                  - otcli-1.1-TEST
                  - otcli-1.1-TEST/lib
                  - otcli-1.1-TEST/lib/otcli-1.1-TEST.jar
                  - otcli-1.1-TEST/lib/kotlin-stdlib-jdk8-1.2.10.jar
                  - otcli-1.1-TEST/lib/kotlinx-coroutines-core-0.21.2.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-cloudfront-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ecs-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ecr-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ec2-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-rds-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-dynamodb-1.11.257.jar
----------
          ID: otcli_rename_extract_path
    Function: file.rename
        Name: /opt/otcli
      Result: True
     Comment: Moved "/opt/otcli-1.1-TEST" to "/opt/otcli"
     Started: 13:46:51.188015
    Duration: 0.544 ms
     Changes:   
              ----------
              /opt/otcli:
                  /opt/otcli-1.1-TEST
----------
          ID: otcli_executable_exists
    Function: file.exists
        Name: /opt/otcli/bin/otcli
      Result: False
     Comment: Specified path /opt/otcli/bin/otcli does not exist
     Started: 13:46:51.188920
    Duration: 0.364 ms
     Changes:   
----------
          ID: otcli_symlink_establlished
    Function: file.symlink
        Name: /usr/sbin/otcli
      Result: False
     Comment: One or more requisite failed: mycompany.otcli.otcli_executable_exists
     Changes:   

Summary for OTDVAPVMXXXX
------------
Succeeded: 3 (changed=3)
Failed:    2
------------
Total states run:     5
Total run time:  58.129 s

Targeting single minion (successful, note all files extracted):

[root@OTCMVM0001 dnasar]# salt -C '*DVAP*XX' state.apply mycompany.otcli
OTDVAPVMXXXX:
----------
          ID: otcli_clear_installation
    Function: file.absent
        Name: /opt/otcli
      Result: True
     Comment: Removed directory /opt/otcli
     Started: 13:30:14.647280
    Duration: 8.119 ms
     Changes:
              ----------
              removed:
                  /opt/otcli
----------
          ID: otcli_extracted
    Function: archive.extracted
        Name: /opt/
      Result: True
     Comment: salt://mycompany/otcli/otcli-1.1-TEST.tar extracted to /opt/, due to absence of one or more files/dirs
     Started: 13:30:14.656165
    Duration: 31116.758 ms
     Changes:
              ----------
              extracted_files:
                  - otcli-1.1-TEST
                  - otcli-1.1-TEST/lib
                  - otcli-1.1-TEST/lib/otcli-1.1-TEST.jar
                  - otcli-1.1-TEST/lib/kotlin-stdlib-jdk8-1.2.10.jar
                  - otcli-1.1-TEST/lib/kotlinx-coroutines-core-0.21.2.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-cloudfront-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ecs-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ecr-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-ec2-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-rds-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-dynamodb-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-s3-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-elasticloadbalancingv2-1.11.257.jar
                  - otcli-1.1-TEST/lib/liquibase-core-3.1.1.jar
                  - otcli-1.1-TEST/lib/kotlin-argparser-2.0.3.jar
                  - otcli-1.1-TEST/lib/konf-0.7.jar
                  - otcli-1.1-TEST/lib/core-0.17.jar
                  - otcli-1.1-TEST/lib/fuel-jackson-1.12.0.jar
                  - otcli-1.1-TEST/lib/postgresql-9.3-1100-jdbc41.jar
                  - otcli-1.1-TEST/lib/kotlin-ant-dsl-0.5.jar
                  - otcli-1.1-TEST/lib/ant-1.9.7.jar
                  - otcli-1.1-TEST/lib/logback-classic-1.3.0-alpha0.jar
                  - otcli-1.1-TEST/lib/slf4j-api-1.8.0-beta0.jar
                  - otcli-1.1-TEST/lib/logback-core-1.3.0-alpha0.jar
                  - otcli-1.1-TEST/lib/kotlin-stdlib-jdk7-1.2.10.jar
                  - otcli-1.1-TEST/lib/xenocom-0.0.5.jar
                  - otcli-1.1-TEST/lib/kotlin-stdlib-jre8-1.2.0.jar
                  - otcli-1.1-TEST/lib/kotlinx-bimap-1.0.jar
                  - otcli-1.1-TEST/lib/kommon-0.14.jar
                  - otcli-1.1-TEST/lib/fuel-1.12.0.jar
                  - otcli-1.1-TEST/lib/kotlin-stdlib-jre7-1.2.0.jar
                  - otcli-1.1-TEST/lib/result-1.2.0.jar
                  - otcli-1.1-TEST/lib/jackson-module-kotlin-2.9.2.jar
                  - otcli-1.1-TEST/lib/kotlin-reflect-1.2.0.jar
                  - otcli-1.1-TEST/lib/kotlin-stdlib-1.2.10.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-kms-1.11.257.jar
                  - otcli-1.1-TEST/lib/aws-java-sdk-core-1.11.257.jar
                  - otcli-1.1-TEST/lib/jmespath-java-1.11.257.jar
                  - otcli-1.1-TEST/lib/snakeyaml-1.19.jar
                  - otcli-1.1-TEST/lib/apiguardian-api-1.0.0.jar
                  - otcli-1.1-TEST/lib/config-1.3.2.jar
                  - otcli-1.1-TEST/lib/jackson-datatype-jsr310-2.9.2.jar
                  - otcli-1.1-TEST/lib/jackson-dataformat-cbor-2.6.7.jar
                  - otcli-1.1-TEST/lib/jackson-databind-2.9.2.jar
                  - otcli-1.1-TEST/lib/jackson-core-2.9.2.jar
                  - otcli-1.1-TEST/lib/jackson-annotations-2.9.2.jar
                  - otcli-1.1-TEST/lib/toml4j-0.7.2.jar
                  - otcli-1.1-TEST/lib/dom4j-2.1.0.jar
                  - otcli-1.1-TEST/lib/ant-launcher-1.9.7.jar
                  - otcli-1.1-TEST/lib/httpclient-4.5.2.jar
                  - otcli-1.1-TEST/lib/commons-logging-1.2.jar
                  - otcli-1.1-TEST/lib/ion-java-1.0.2.jar
                  - otcli-1.1-TEST/lib/joda-time-2.8.1.jar
                  - otcli-1.1-TEST/lib/guava-20.0.jar
                  - otcli-1.1-TEST/lib/gson-2.8.1.jar
                  - otcli-1.1-TEST/lib/jaxen-1.1.6.jar
                  - otcli-1.1-TEST/lib/httpcore-4.4.4.jar
                  - otcli-1.1-TEST/lib/commons-codec-1.9.jar
                  - otcli-1.1-TEST/lib/annotations-13.0.jar
                  - otcli-1.1-TEST/bin
                  - otcli-1.1-TEST/bin/otcli
                  - otcli-1.1-TEST/bin/otcli.bat
----------
          ID: otcli_rename_extract_path
    Function: file.rename
        Name: /opt/otcli
      Result: True
     Comment: Moved "/opt/otcli-1.1-TEST" to "/opt/otcli"
     Started: 13:30:45.773296
    Duration: 0.582 ms
     Changes:
              ----------
              /opt/otcli:
                  /opt/otcli-1.1-TEST
----------
          ID: otcli_executable_exists
    Function: file.exists
        Name: /opt/otcli/bin/otcli
      Result: True
     Comment: Path /opt/otcli/bin/otcli exists
     Started: 13:30:45.774241
    Duration: 0.349 ms
     Changes:
----------
          ID: otcli_symlink_establlished
    Function: file.symlink
        Name: /usr/sbin/otcli
      Result: True
     Comment: Symlink /usr/sbin/otcli is present and owned by root:root
     Started: 13:30:45.774915
    Duration: 0.796 ms
     Changes:

Summary for OTDVAPVMXXXX
------------
Succeeded: 5 (changed=3)
Failed:    0
------------
Total states run:     5
Total run time:  31.127 s

Versions Report

[root@OTDVAPVMXXXX dnasar]# salt-call --versions-report
Salt Version:
           Salt: 2018.3.0

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: 2.1
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.7.2
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.6
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 2.7.12 (default, Nov  2 2017, 19:20:38)
   python-gnupg: Not Installed
         PyYAML: 3.10
          PyZMQ: 14.5.0
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.0.5

System Versions:
           dist:
         locale: UTF-8
        machine: x86_64
        release: 4.9.62-21.56.amzn1.x86_64
         system: Linux
        version: Not Installed
devinnasar commented 6 years ago

Master logfile: master.log

devinnasar commented 6 years ago

Log tail from minion:

[root@OTDVAPVMXXXX dnasar]# tail -f /var/log/salt/minion
2018-05-04 14:10:41,092 [salt.minion                                           :1854][INFO    ][22040] Returning information for job: 20180504141041068653
2018-05-04 14:11:14,852 [salt.minion                                           :1422][INFO    ][28032] User sudo_dnasar Executingcommand state.apply with jid 20180504141114847682
2018-05-04 14:11:14,864 [salt.minion                                           :1557][INFO    ][22069] Starting a new job with PID 22069
2018-05-04 14:11:22,682 [salt.state                                            :905 ][INFO    ][22069] Loading fresh modules for state activity
2018-05-04 14:11:22,790 [salt.state                                            :1762][INFO    ][22069] Running state [/opt/otcli]at time 14:11:22.790948
2018-05-04 14:11:22,791 [salt.state                                            :1795][INFO    ][22069] Executing state file.absent for [/opt/otcli]
2018-05-04 14:11:22,802 [salt.state                                            :290 ][INFO    ][22069] {u'removed': u'/opt/otcli'}
2018-05-04 14:11:22,803 [salt.state                                            :1943][INFO    ][22069] Completed state [/opt/otcli] at time 14:11:22.803044 (duration_in_ms=12.095)
2018-05-04 14:11:22,803 [salt.state                                            :1762][INFO    ][22069] Running state [/opt/] at time 14:11:22.803776
2018-05-04 14:11:22,803 [salt.state                                            :1795][INFO    ][22069] Executing state archive.extracted for [/opt/]
2018-05-04 14:11:47,244 [salt.utils.schedule                                   :1375][INFO    ][28032] Running scheduled job: __mine_interval
2018-05-04 14:11:47,283 [salt.loaded.int.module.cmdmod                         :385 ][INFO    ][22084] Executing command 'cat /etc/ssh/ssh_host_*_key.pub' in directory '/root'
2018-05-04 14:12:22,846 [salt.fileclient                                       :1259][INFO    ][22069] Fetching file from saltenv 'base', ** done ** 'opentempo/otcli/otcli-1.1-TEST.tar'
2018-05-04 14:12:22,941 [salt.state                                            :290 ][INFO    ][22069] {u'extracted_files': ['otcli-1.1-TEST', 'otcli-1.1-TEST/lib', 'otcli-1.1-TEST/lib/otcli-1.1-TEST.jar', 'otcli-1.1-TEST/lib/kotlin-stdlib-jdk8-1.2.10.jar', 'otcli-1.1-TEST/lib/kotlinx-coroutines-core-0.21.2.jar', 'otcli-1.1-TEST/lib/aws-java-sdk-cloudfront-1.11.257.jar', 'otcli-1.1-TEST/lib/aws-java-sdk-ecs-1.11.257.jar']}
2018-05-04 14:12:22,942 [salt.state                                            :1943][INFO    ][22069] Completed state [/opt/] at time 14:12:22.941979 (duration_in_ms=60138.202)
2018-05-04 14:12:22,942 [salt.state                                            :1762][INFO    ][22069] Running state [/opt/otcli] at time 14:12:22.942368
2018-05-04 14:12:22,942 [salt.state                                            :1795][INFO    ][22069] Executing state file.rename for [/opt/otcli]
2018-05-04 14:12:22,943 [salt.state                                            :290 ][INFO    ][22069] {u'/opt/otcli': u'/opt/otcli-1.1-TEST'}
2018-05-04 14:12:22,943 [salt.state                                            :1943][INFO    ][22069] Completed state [/opt/otcli] at time 14:12:22.943387 (duration_in_ms=1.019)
2018-05-04 14:12:22,943 [salt.state                                            :1762][INFO    ][22069] Running state [/opt/otcli/bin/otcli] at time 14:12:22.943832
2018-05-04 14:12:22,944 [salt.state                                            :1795][INFO    ][22069] Executing state file.exists for [/opt/otcli/bin/otcli]
2018-05-04 14:12:22,944 [salt.state                                            :292 ][ERROR   ][22069] Specified path /opt/otcli/bin/otcli does not exist
2018-05-04 14:12:22,944 [salt.state                                            :1943][INFO    ][22069] Completed state [/opt/otcli/bin/otcli] at time 14:12:22.944881 (duration_in_ms=1.049)
2018-05-04 14:12:22,946 [salt.minion                                           :1854][INFO    ][22069] Returning information for job: 20180504141114847682
^[2018-05-04 14:13:46,245 [salt.utils.schedule                                   :1375][INFO    ][28032] Running scheduled job: __mine_interval
2018-05-04 14:13:46,290 [salt.loaded.int.module.cmdmod                         :385 ][INFO    ][22096] Executing command 'cat /etc/ssh/ssh_host_*_key.pub' in directory '/root'
2018-05-04 14:15:46,245 [salt.utils.schedule                                   :1375][INFO    ][28032] Running scheduled job: __mine_interval
2018-05-04 14:15:46,284 [salt.loaded.int.module.cmdmod                         :385 ][INFO    ][22226] Executing command 'cat /etc/ssh/ssh_host_*_key.pub' in directory '/root
garethgreenaway commented 6 years ago

@devinnasar Thanks for the report. Using a simplified version of your state included above, I haven't been able to reproduce the issue. Are you able to comment everything in the state out and go through in stages to hopefully narrow down if a particular section is causing the issue with multiple minions? You mentioned using S3 but it appears you're using the Salt fileserver, are you using the s3fs Salt fileserver?

stale[bot] commented 5 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

If this issue is closed prematurely, please leave a comment and we will gladly reopen the issue.