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.

Sign up for GitHub

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

Jump to bottom

[BUG] salt generated version php.ini missing in php-cli directory, when installing php-fpm and php-cli. #200

Closed
gj02ib65 opened this issue Oct 4, 2019 · 4 comments
Closed

[BUG] salt generated version php.ini missing in php-cli directory, when installing php-fpm and php-cli. #200

gj02ib65 opened this issue Oct 4, 2019 · 4 comments
Labels
bug

Comments

@gj02ib65
Copy link

gj02ib65 commented Oct 4, 2019 •
edited by myii
Loading

I am looking for some assistance with php saltstack formula. I need php-fmp and php-cli. The php.ini file is getting built and placed in the fmp folder, but the cli version of php.ini is not getting built. I am sure I am doing something wrong but I can not put on my finger on it. Following is salt information. I will attach my pillar/php.sls file as well.

Describe the bug

I am trying to install PHP with php-fpm and php-cli. The salt managed php.ini file is written to the php-fpm directory. However, the php.ini file in the php-cli directory is the default file, rather than the salt managed version of the file.

My assumption is that I have improperly defined the php.sls file. I have been testing and have made changes to the php.sls file in an attempt to get the functionality working properly.

Setup

Running the formula using:

$ sudo salt '*worker*' state.apply php

php.zip -- extracted below as well:

# -*- coding: utf-8 -*-
# vim: ft=yaml
---
## php pillar examples

{% set phpversion = '7.0' %}
 
php:
  # Use the following values to mute deprecation warnings
  warning_messages:
    v1.0.0:
      mute_critical: true
      mute_upcoming: true
  # Use external repository instead the default (only Ubuntu family)
  use_external_repo: true
  # Set the external repository name (valid only if use_external_repo is not none)
  external_repo_name: 'ondrej/php'
  # Use Software Collections Repository offering PHP 5.4, 5.5, 5.6, 7.0 and 7.1
  # https://www.softwarecollections.org/en/ for more information.
  # SCL is only supported on RHEL and CentOS
  use_scl_repo: true
  # Which PHP version from the SCL repos to use
  scl_php_version: 71
  # Set the MongoDB driver version. You can specify (optionally) the driver version
  # when you add the php.mongo formula to your execution list
  mongo_version: "1.5.5"
  # set the version of php to be used
  version: {{ phpversion }}
  # can be a list of versions :
  # version:
  #   - "7.3"
  #   - "7.2"

  # set the version for the Debian alternatives system, when using a list of versions,
  # php:version is used otherwise.
  alternatives_version: "7.2"

  # this section contains mostly grain filtered data, while overrides
  # are possible in the pillar for unique cases, if your OS is not
  # represented, please consider adding it to the map.jinja for
  # upstream inclusion
  lookup:
    enable_php_repo: centos-sclo-rh-testing
    # package definitions, these can be strings, lists of strings, or
    # lists of dictionaries
    pkgs:
      # memcached: php5-memcached
      # ensures both will be installed
      curl:
        - php-common
        - curl
      # a dictionary can be used in more complex cases where you want
      # to pass forward special arguments to the pkg.installed call
      # you MUST include the name argument for this to work
      cli:
        -
          name: php-cli
          fromrepo: my-specialrepo
        -
          name: php-common
          skip_verify: true
      #fpm: php-fpm

     # php-fpm os-specific settings
    fpm:
      ini: /etc/php/{{ phpversion }}/fpm/php.ini
      conf: /etc/php/{{ phpversion }}/fpm/config.conf
      pools: /etc/php/{{ phpversion }}/fpm/pool.d
      service: php{{ phpversion }}-fpm

      # the default content of the php5-fpm main config file
      defaults:
        global:
          pid: /var/run/php{{ phpversion }}-fpm.pid

    # php-cli os-specific settings
    cli:
      ini: /etc/php/{{ phpversion }}/cli/php.ini

  # php-fpm settings
  fpm:
    # settings for the php-fpm service
    service:
      # if true, enables the php-fpm service, if false disables it
      enabled: true
      # additional arguments passed forward to
      # service.enabled/disabled
      opts:
        reload: true

    # settings for the relevant php-fpm configuration files
    config:

      # options to manage the php.ini file used by php-fpm
      ini:
        # arguments passed through to file.managed
        opts:
          recurse: true
        # php.ini file contents that will be merged with the
        # defaults in php.ini.defaults. See php.ini.defaults for
        # syntax guidelines.
        settings:
          PHP:
            engine: 'On'
            extension_dir: '/usr/lib/php/modules/'
            extension: [pdo_mysql.so, iconv.so, openssl.so]
            expose_php: 'Off'
            default_charset: "UTF-8"

      # options to manage the php-fpm conf file
      conf:
        # arguments passed through to file.managed
        opts:
          recurse: true
        # php-fpm conf file contents that will be merged with
        # php.lookup.fpm.defaults. See php.ini.defaults for
        # ini-style syntax guidelines.
        settings:
          global:
            pid: /var/run/fpm/special-pid.file

    # settings for fpm-pools
    pools:
      # defaults will apply for each pools settings and can be overwritten
      # by pool settings
      defaults:
        user: www-data
        group: www-data
        listen: /var/run/fpm-default.sock

      # name of the pool file to be managed, this will be appended
      # to the path specified in php.lookup.fpm.pools
      'mypool.conf':
        # If true, the pool file will be managed, if false it will be
        # absent
        enabled: true

        # Overwrite the filename for ext_pillar that doesn't allow
        # dots in fields names.
        filname: my_other_name.conf

        # arguments passed forward to file.managed or file.absent
        opts:
          replace: false

        # pool file contents. See php.ini.defaults for ini-style
        # syntax guidelines.
        settings:
          myapp:
            user: www-data
            group: www-data
            listen: /var/run/php{{ phpversion }}-fpm-myapp.sock
            listen.owner: www-data
            listen.group: www-data
            listen.mode: 0660
            pm: dynamic
            pm.max_children: 5
            pm.start_servers: 2
            pm.min_spare_servers: 1
            pm.max_spare_servers: 3
            'php_admin_value[memory_limit]': 300M

  # php-cli settings
  cli:
    # settings to manage the cli's php.ini
    config:
      ini:
        # opts passed forward directly to file.managed
        opts:
          # replace: true
        # contents of the php.ini file that are merged with defaults
        # from php.ini.defaults. See php.ini.defaults for ini-style
        # syntax guidelines
        settings:
          PHP:
            engine: 'on'
            realpath_cache_size: 16k
            memory_limit: 256M
            display_errors: stderr
            auto_prepend_file: /usr/local/share/reach/global/global.php
            include_path: ".:/usr/local/share/reach/global"
            extension: redis.so


  # php-xcache settings
  xcache:
    ini:
      opts: {}
      # contents of the xcache.ini file that are merged with defaults
      # from php.xcache.ini.defaults. See php.ini.defaults for ini-style
      settings:
        xcache:
          xcache.size: 90M

  # global php.ini settings
  ini:
    # Default php.ini contents. These follow a strict format. The top-
    # level dict keys form ini group headings. Nested key/value
    # pairs represent setting=value statements. If a value is a list,
    # its contents will be joined by commas in final rendering.
    defaults:
      PHP:
        engine: 'On'
        output_buffering: 4096
        disable_functions:
          - pcntl_alarm
          - pcntl_fork
          - pcntl_wait
          - pcntl_waitpid
          - pcntl_wifexited
          - pcntl_wifstopped
          - pcntl_wifsignaled
          - pcntl_wifcontinued
          - pcntl_wexitstatus
          - pcntl_wtermsig
          - pcntl_wstopsig
          - pcntl_signal
          - pcntl_signal_dispatch
          - pcntl_get_last_error
          - pcntl_strerror
          - pcntl_sigprocmask
          - pcntl_sigwaitinfo
          - pcntl_sigtimedwait
          - pcntl_exec
          - pcntl_getpriority
          - pcntl_setpriority
      'CLI Server':
        cli_server.color: 'On'

  # List of modules to install via php.modules
  modules:
    # Calls `php.<name>` if available, or try to install the matching
    # packages that can be set via from php:lookup:pkgs
    - cli
    - fpm
    - curl
    - mysql
    - bcmath
    - composer
    - dev
    - gd
    - gmp
    - json
    - ldap
    - mbstring
    - opcache
    - sqlite
    - sybase
    - xml
    - redis
    - pear
    - mongodb
    - mcrypt

  # When using php.apache2 on FreeBSD:
  # Set this to false if you're not using apache-formula
  use_apache_formula: true

  tofs:
    # The files_switch key serves as a selector for alternative
    # directories under the formula files directory. See TOFS pattern
    # doc for more info.
    # Note: Any value not evaluated by `config.get` will be used literally.
    # This can be used to set custom paths, as many levels deep as required.
    # files_switch:
    #   - any/path/can/be/used/here
    #   - id
    #   - role
    #   - osfinger
    #   - os
    #   - os_family
    # All aspects of path/file resolution are customisable using the options below.
    # This is unnecessary in most cases; there are sensible defaults.
    # path_prefix: template_alt
    # dirs:
    #   files: files_alt
    #   default: default_alt
    source_files:
      php_apache2_ini:
        - alt_php.ini
      php_apache2_module_config:
        - alt_mod_php.conf.jinja
      php_cli_ini:      # Used if there is only one version declared
        - alt_php.ini
      php_cli_ini_7.2:  # Used if several versions are declared
        - alt_php.ini
      php_fpm_conf_config:
        - alt_php.ini
      php_fpm_conf_config_7.3:
        - alt_php.ini
      php_fpm_ini_config:
        - alt_php.ini
      php_fpm_ini_config_7.0:
        - alt_php.ini
      php_fpm_pool_conf:
        - alt_php.ini
      php_hhvm_conf_config:
        - alt_php.ini
      php_hhvm_ini_config:
        - alt_php.ini
      php_xcache_ini:
        - alt_php.ini

Steps to reproduce the bug

Expected behaviour

Versions report

Salt Version:
          Salt: 2019.2.0

Dependency Versions:
          cffi: Not Installed
      cherrypy: Not Installed
      dateutil: 2.6.1
     docker-py: Not Installed
         gitdb: 2.0.3
     gitpython: 2.1.8
         ioflo: Not Installed
        Jinja2: 2.10
       libgit2: 0.26.0
       libnacl: Not Installed
      M2Crypto: Not Installed
          Mako: 1.0.7
  msgpack-pure: Not Installed
msgpack-python: 0.5.6
  mysql-python: Not Installed
     pycparser: Not Installed
      pycrypto: 2.6.1
  pycryptodome: Not Installed
        pygit2: 0.26.2
        Python: 2.7.15+ (default, Jul  9 2019, 16:51:35)
  python-gnupg: 0.4.1
        PyYAML: 3.12
         PyZMQ: 16.0.2
          RAET: Not Installed
         smmap: 2.0.3
       timelib: Not Installed
       Tornado: 4.5.3
           ZMQ: 4.2.5System Versions:
          dist: Ubuntu 18.04 bionic
        locale: UTF-8
       machine: x86_64
       release: 5.0.0-1020-azure
        system: Linux
       version: Ubuntu 18.04 bionic

Additional context

Optional: How can this template be improved?
@gj02ib65 gj02ib65 added the bug label Oct 4, 2019
@gj02ib65 gj02ib65 mentioned this issue Oct 4, 2019
Open
@gj02ib65
Copy link
Author

gj02ib65 commented Oct 4, 2019 •
edited by myii
Loading

I commented out the total tofs section of pillar/php.sls. Then created a newly built minion with salt-minion running in debug mode. First run state.apply pip and then state.apply php. The result is that the php.ini file in /etc/php/7.0/cli is the default php.ini file. Not managed by Salt. And the fpm directory is missing completely.

minion.log

2019-10-04 16:35:57,712 [salt.utils.network:1963][ERROR   ][5241] DNS lookup or connection check of 'salt' failed.
2019-10-04 16:35:57,713 [salt.minion      :165 ][ERROR   ][5241] Master hostname: 'salt' not found or not responsive. Retrying in 30 seconds
2019-10-04 16:36:03,682 [salt.utils.parsers:1071][WARNING ][5241] Minion received a SIGTERM. Exiting.
2019-10-04 16:36:05,182 [salt.utils.network:1963][ERROR   ][5684] DNS lookup or connection check of 'salt' failed.
2019-10-04 16:36:05,183 [salt.minion      :165 ][ERROR   ][5684] Master hostname: 'salt' not found or not responsive. Retrying in 30 seconds
2019-10-04 16:36:35,217 [salt.utils.network:1963][ERROR   ][5684] DNS lookup or connection check of 'salt' failed.
2019-10-04 16:36:35,218 [salt.minion      :165 ][ERROR   ][5684] Master hostname: 'salt' not found or not responsive. Retrying in 30 seconds
2019-10-04 16:36:40,210 [salt.utils.parsers:1071][WARNING ][5684] Minion received a SIGTERM. Exiting.
2019-10-04 16:36:41,057 [salt.utils.verify:558 ][WARNING ][5852] Insecure logging configuration detected! Sensitive data may be logged.
2019-10-04 16:36:41,058 [salt.cli.daemons :298 ][INFO    ][5852] Setting up the Salt Minion "ussc-tst-worker-vm1"
2019-10-04 16:36:41,105 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'base64_encode' as a jinja filter
2019-10-04 16:36:41,105 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'base64_decode' as a jinja filter
2019-10-04 16:36:41,105 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'md5' as a jinja filter
2019-10-04 16:36:41,106 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'sha256' as a jinja filter
2019-10-04 16:36:41,106 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'sha512' as a jinja filter
2019-10-04 16:36:41,106 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'hmac' as a jinja filter
2019-10-04 16:36:41,106 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'random_hash' as a jinja filter
2019-10-04 16:36:41,107 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'rand_str' as a jinja filter
2019-10-04 16:36:41,107 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'file_hashsum' as a jinja filter
2019-10-04 16:36:41,198 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'http_query' as a jinja filter
2019-10-04 16:36:41,200 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'strftime' as a jinja filter
2019-10-04 16:36:41,200 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'date_format' as a jinja filter
2019-10-04 16:36:41,201 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'yaml_dquote' as a jinja filter
2019-10-04 16:36:41,201 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'yaml_squote' as a jinja filter
2019-10-04 16:36:41,201 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'yaml_encode' as a jinja filter
2019-10-04 16:36:41,204 [salt.utils.decorators.jinja:81  ][DEBUG   ][5852] Marking 'raise' as a jinja global
2019-10-04 16:36:41,204 [salt.utils.decorators.jinja:56  ][DEBUG   ][5852] Marking 'match' as a jinja test
2019-10-04 16:36:41,204 [salt.utils.decorators.jinja:56  ][DEBUG   ][5852] Marking 'equalto' as a jinja test
2019-10-04 16:36:41,205 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'skip' as a jinja filter
2019-10-04 16:36:41,205 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'sequence' as a jinja filter
2019-10-04 16:36:41,205 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'to_bool' as a jinja filter
2019-10-04 16:36:41,205 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'tojson' as a jinja filter
2019-10-04 16:36:41,206 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'quote' as a jinja filter
2019-10-04 16:36:41,206 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'regex_escape' as a jinja filter
2019-10-04 16:36:41,206 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'regex_search' as a jinja filter
2019-10-04 16:36:41,206 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'regex_match' as a jinja filter
2019-10-04 16:36:41,207 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'regex_replace' as a jinja filter
2019-10-04 16:36:41,207 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'uuid' as a jinja filter
2019-10-04 16:36:41,207 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'unique' as a jinja filter
2019-10-04 16:36:41,207 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'min' as a jinja filter
2019-10-04 16:36:41,208 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'max' as a jinja filter
2019-10-04 16:36:41,208 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'avg' as a jinja filter
2019-10-04 16:36:41,208 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'union' as a jinja filter
2019-10-04 16:36:41,208 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'intersect' as a jinja filter
2019-10-04 16:36:41,209 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'difference' as a jinja filter
2019-10-04 16:36:41,209 [salt.utils.decorators.jinja:31  ][DEBUG   ][5852] Marking 'symmetric_difference' as a jinja filter
2019-10-04 16:36:41,216 [salt.utils.process:206 ][DEBUG   ][5852] Created pidfile: /var/run/salt-minion.pid
2019-10-04 16:36:41,216 [salt.cli.daemons :85  ][INFO    ][5852] Starting up the Salt Minion
2019-10-04 16:36:41,217 [salt.utils.event :982 ][DEBUG   ][5852] AsyncEventPublisher PUB socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pub.ipc
2019-10-04 16:36:41,217 [salt.utils.event :984 ][DEBUG   ][5852] AsyncEventPublisher PULL socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pull.ipc
2019-10-04 16:36:41,217 [salt.utils.event :1020][INFO    ][5852] Starting pull socket on /var/run/salt/minion/minion_event_c5b2bc5cd3_pull.ipc
2019-10-04 16:36:41,220 [salt.utils.event :323 ][DEBUG   ][5852] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pub.ipc
2019-10-04 16:36:41,221 [salt.utils.event :324 ][DEBUG   ][5852] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pull.ipc
2019-10-04 16:36:41,223 [salt.loader      :747 ][DEBUG   ][5852] Grains refresh requested. Refreshing grains.
2019-10-04 16:36:41,223 [salt.config      :2185][DEBUG   ][5852] Reading configuration from /etc/salt/minion
2019-10-04 16:36:41,679 [salt.minion      :1150][INFO    ][5852] Creating minion process manager
2019-10-04 16:36:41,680 [salt.utils.process:515 ][DEBUG   ][5852] Process Manager starting!
2019-10-04 16:36:41,680 [salt.utils.process:515 ][DEBUG   ][5852] Process Manager starting!
2019-10-04 16:36:41,706 [salt.minion      :725 ][DEBUG   ][5852] Connecting to master. Attempt 1 of 1
2019-10-04 16:36:41,706 [salt.utils.network:2013][DEBUG   ][5852] "prd-ssm.reachcm.com" Not an IP address? Assuming it is a hostname.
2019-10-04 16:36:41,785 [salt.minion      :236 ][DEBUG   ][5852] Master URI: tcp://40.122.203.8:34506
2019-10-04 16:36:41,803 [salt.crypt       :464 ][DEBUG   ][5852] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:36:41,804 [salt.crypt       :796 ][INFO    ][5852] Generating keys: /etc/salt/pki/minion
2019-10-04 16:36:41,901 [salt.crypt       :200 ][DEBUG   ][5852] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:36:41,901 [salt.crypt       :180 ][DEBUG   ][5852] salt.crypt._get_key_with_evict: Loading private key
2019-10-04 16:36:41,902 [salt.crypt       :802 ][DEBUG   ][5852] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:36:41,904 [salt.transport.zeromq:449 ][DEBUG   ][5852] Generated random reconnect delay between '1000ms' and '11000ms' (4601)
2019-10-04 16:36:41,904 [salt.transport.zeromq:452 ][DEBUG   ][5852] Setting zmq_reconnect_ivl to '4601ms'
2019-10-04 16:36:41,905 [salt.transport.zeromq:458 ][DEBUG   ][5852] Setting zmq_reconnect_ivl_max to '11000ms'
2019-10-04 16:36:41,906 [salt.transport.zeromq:138 ][DEBUG   ][5852] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', 'clear')
2019-10-04 16:36:41,906 [salt.transport.zeromq:209 ][DEBUG   ][5852] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:36:41,907 [salt.transport.zeromq:1189][DEBUG   ][5852] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:36:41,907 [salt.crypt       :208 ][DEBUG   ][5852] salt.crypt.get_rsa_pub_key: Loading public key
2019-10-04 16:36:42,004 [salt.crypt       :757 ][ERROR   ][5852] The Salt Master has cached the public key for this node, this salt minion will wait for 10 seconds before attempting to re-authenticate
2019-10-04 16:36:42,004 [salt.crypt       :627 ][INFO    ][5852] Waiting 10 seconds before retry.
2019-10-04 16:36:52,005 [salt.crypt       :208 ][DEBUG   ][5852] salt.crypt.get_rsa_pub_key: Loading public key
2019-10-04 16:36:52,032 [salt.crypt       :757 ][ERROR   ][5852] The Salt Master has cached the public key for this node, this salt minion will wait for 10 seconds before attempting to re-authenticate
2019-10-04 16:36:52,033 [salt.crypt       :627 ][INFO    ][5852] Waiting 10 seconds before retry.
2019-10-04 16:37:02,042 [salt.crypt       :208 ][DEBUG   ][5852] salt.crypt.get_rsa_pub_key: Loading public key
2019-10-04 16:37:02,070 [salt.crypt       :757 ][ERROR   ][5852] The Salt Master has cached the public key for this node, this salt minion will wait for 10 seconds before attempting to re-authenticate
2019-10-04 16:37:02,070 [salt.crypt       :627 ][INFO    ][5852] Waiting 10 seconds before retry.
2019-10-04 16:37:12,080 [salt.crypt       :208 ][DEBUG   ][5852] salt.crypt.get_rsa_pub_key: Loading public key
2019-10-04 16:37:12,106 [salt.crypt       :757 ][ERROR   ][5852] The Salt Master has cached the public key for this node, this salt minion will wait for 10 seconds before attempting to re-authenticate
2019-10-04 16:37:12,107 [salt.crypt       :627 ][INFO    ][5852] Waiting 10 seconds before retry.
2019-10-04 16:37:22,116 [salt.crypt       :208 ][DEBUG   ][5852] salt.crypt.get_rsa_pub_key: Loading public key
2019-10-04 16:37:22,143 [salt.crypt       :757 ][ERROR   ][5852] The Salt Master has cached the public key for this node, this salt minion will wait for 10 seconds before attempting to re-authenticate
2019-10-04 16:37:22,143 [salt.crypt       :627 ][INFO    ][5852] Waiting 10 seconds before retry.
2019-10-04 16:37:32,153 [salt.crypt       :208 ][DEBUG   ][5852] salt.crypt.get_rsa_pub_key: Loading public key
2019-10-04 16:37:32,184 [salt.crypt       :873 ][DEBUG   ][5852] Decrypting the current master AES key
2019-10-04 16:37:32,184 [salt.crypt       :200 ][DEBUG   ][5852] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:37:32,184 [salt.crypt       :802 ][DEBUG   ][5852] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:37:32,187 [salt.crypt       :208 ][DEBUG   ][5852] salt.crypt.get_rsa_pub_key: Loading public key
2019-10-04 16:37:32,189 [salt.transport.zeromq:233 ][DEBUG   ][5852] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:37:32,190 [salt.transport.zeromq:509 ][DEBUG   ][5852] Connecting the Minion to the Master publish port, using the URI: tcp://40.122.203.8:34505
2019-10-04 16:37:32,190 [salt.crypt       :200 ][DEBUG   ][5852] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:37:32,190 [salt.crypt       :802 ][DEBUG   ][5852] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:37:32,193 [salt.transport.zeromq:138 ][DEBUG   ][5852] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:37:32,193 [salt.crypt       :472 ][DEBUG   ][5852] Re-using AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:37:32,194 [salt.transport.zeromq:209 ][DEBUG   ][5852] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:37:32,194 [salt.transport.zeromq:1189][DEBUG   ][5852] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:37:32,523 [salt.crypt       :200 ][DEBUG   ][5852] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:37:32,524 [salt.crypt       :802 ][DEBUG   ][5852] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:37:32,527 [salt.transport.zeromq:233 ][DEBUG   ][5852] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:37:32,528 [salt.loader      :747 ][DEBUG   ][5852] Grains refresh requested. Refreshing grains.
2019-10-04 16:37:32,528 [salt.config      :2185][DEBUG   ][5852] Reading configuration from /etc/salt/minion
2019-10-04 16:37:32,737 [salt.utils.schedule:94  ][DEBUG   ][5852] Initializing new Schedule
2019-10-04 16:37:32,744 [salt.utils.lazy  :104 ][DEBUG   ][5852] LazyLoaded timezone.get_offset
2019-10-04 16:37:32,745 [salt.utils.lazy  :104 ][DEBUG   ][5852] LazyLoaded cmd.run
2019-10-04 16:37:32,746 [salt.loader.prd-ssm.reachcm.com:34506.int.module.cmdmod:397 ][INFO    ][5852] Executing command [u'date', u'+%z'] in directory '/root'
2019-10-04 16:37:32,757 [salt.loader.prd-ssm.reachcm.com:34506.int.module.cmdmod:843 ][DEBUG   ][5852] stdout: +0000
2019-10-04 16:37:32,757 [salt.loader.prd-ssm.reachcm.com:34506.int.module.cmdmod:1202][DEBUG   ][5852] output: +0000
2019-10-04 16:37:32,762 [salt.utils.lazy  :104 ][DEBUG   ][5852] LazyLoaded config.merge
2019-10-04 16:37:32,763 [salt.utils.event :323 ][DEBUG   ][5852] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pub.ipc
2019-10-04 16:37:32,763 [salt.utils.event :324 ][DEBUG   ][5852] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pull.ipc
2019-10-04 16:37:32,764 [salt.utils.event :738 ][DEBUG   ][5852] Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {u'_stamp': '2019-10-04T16:37:32.764337', u'complete': True, u'schedule': {}}
2019-10-04 16:37:32,764 [salt.utils.schedule:271 ][DEBUG   ][5852] Persisting schedule
2019-10-04 16:37:32,765 [salt.transport.ipc:364 ][DEBUG   ][5852] Closing IPCMessageClient instance
2019-10-04 16:37:32,766 [salt.utils.lazy  :104 ][DEBUG   ][5852] LazyLoaded mine.update
2019-10-04 16:37:32,766 [salt.utils.schedule:376 ][INFO    ][5852] Added new job __mine_interval to scheduler
2019-10-04 16:37:32,767 [salt.utils.event :323 ][DEBUG   ][5852] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pub.ipc
2019-10-04 16:37:32,767 [salt.utils.event :324 ][DEBUG   ][5852] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pull.ipc
2019-10-04 16:37:32,768 [salt.utils.event :738 ][DEBUG   ][5852] Sending event: tag = /salt/minion/minion_schedule_add_complete; data = {u'_stamp': '2019-10-04T16:37:32.768235', u'complete': True, u'schedule': {u'__mine_interval': {u'function': u'mine.update', u'run_on_start': True, u'enabled': True, u'return_job': False, u'jid_include': True, u'maxrunning': 2, u'minutes': 60}}}
2019-10-04 16:37:32,768 [salt.utils.schedule:271 ][DEBUG   ][5852] Persisting schedule
2019-10-04 16:37:32,769 [salt.transport.ipc:364 ][DEBUG   ][5852] Closing IPCMessageClient instance
2019-10-04 16:37:32,769 [salt.minion      :1287][INFO    ][5852] Added mine.update to scheduler
2019-10-04 16:37:32,770 [salt.utils.event :323 ][DEBUG   ][5852] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pub.ipc
2019-10-04 16:37:32,770 [salt.utils.event :324 ][DEBUG   ][5852] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pull.ipc
2019-10-04 16:37:32,771 [salt.utils.event :738 ][DEBUG   ][5852] Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {u'_stamp': '2019-10-04T16:37:32.771005', u'complete': True, u'schedule': {u'__mine_interval': {u'function': u'mine.update', u'run_on_start': True, u'enabled': True, u'return_job': False, u'jid_include': True, u'maxrunning': 2, u'minutes': 60}}}
2019-10-04 16:37:32,771 [salt.utils.schedule:271 ][DEBUG   ][5852] Persisting schedule
2019-10-04 16:37:32,772 [salt.transport.ipc:364 ][DEBUG   ][5852] Closing IPCMessageClient instance
2019-10-04 16:37:32,772 [salt.utils.event :323 ][DEBUG   ][5852] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pub.ipc
2019-10-04 16:37:32,772 [salt.utils.event :324 ][DEBUG   ][5852] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pull.ipc
2019-10-04 16:37:32,773 [salt.utils.event :738 ][DEBUG   ][5852] Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {u'_stamp': '2019-10-04T16:37:32.773423', u'complete': True, u'schedule': {u'__mine_interval': {u'function': u'mine.update', u'run_on_start': True, u'enabled': True, u'return_job': False, u'jid_include': True, u'maxrunning': 2, u'minutes': 60}}}
2019-10-04 16:37:32,774 [salt.utils.schedule:271 ][DEBUG   ][5852] Persisting schedule
2019-10-04 16:37:32,774 [salt.transport.ipc:364 ][DEBUG   ][5852] Closing IPCMessageClient instance
2019-10-04 16:37:32,776 [salt.minion      :2320][INFO    ][5852] Minion is starting as user 'root'
2019-10-04 16:37:32,777 [salt.minion      :2682][DEBUG   ][5852] Minion 'ussc-tst-worker-vm1' trying to tune in
2019-10-04 16:37:32,777 [salt.transport.zeromq:138 ][DEBUG   ][5852] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:37:32,777 [salt.crypt       :464 ][DEBUG   ][5852] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:37:32,778 [salt.transport.zeromq:209 ][DEBUG   ][5852] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:37:32,779 [salt.transport.zeromq:1189][DEBUG   ][5852] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:37:32,877 [salt.transport.zeromq:233 ][DEBUG   ][5852] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:37:32,878 [salt.transport.zeromq:138 ][DEBUG   ][5852] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:37:32,878 [salt.crypt       :464 ][DEBUG   ][5852] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:37:32,878 [salt.transport.zeromq:209 ][DEBUG   ][5852] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:37:32,879 [salt.transport.zeromq:1189][DEBUG   ][5852] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:37:32,975 [salt.transport.zeromq:233 ][DEBUG   ][5852] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:37:32,976 [salt.minion      :2692][INFO    ][5852] Minion is ready to receive requests!
2019-10-04 16:37:32,979 [salt.minion      :2357][DEBUG   ][5852] Minion of 'prd-ssm.reachcm.com' is handling event tag '/salt/minion/minion_schedule_delete_complete'
2019-10-04 16:37:32,980 [salt.minion      :2357][DEBUG   ][5852] Minion of 'prd-ssm.reachcm.com' is handling event tag '/salt/minion/minion_schedule_add_complete'
2019-10-04 16:37:32,980 [salt.minion      :2357][DEBUG   ][5852] Minion of 'prd-ssm.reachcm.com' is handling event tag '/salt/minion/minion_schedule_delete_complete'
2019-10-04 16:37:32,980 [salt.minion      :2357][DEBUG   ][5852] Minion of 'prd-ssm.reachcm.com' is handling event tag '/salt/minion/minion_schedule_delete_complete'
2019-10-04 16:37:33,980 [salt.utils.schedule:1636][DEBUG   ][5852] schedule: Job __mine_interval was scheduled with jid_include, adding to cache (jid_include defaults to True)
2019-10-04 16:37:33,980 [salt.utils.schedule:1639][DEBUG   ][5852] schedule: Job __mine_interval was scheduled with a max number of 2
2019-10-04 16:37:33,980 [salt.utils.schedule:1656][INFO    ][5852] Running scheduled job: __mine_interval
2019-10-04 16:37:33,985 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:2-Schedule-__mine_interval added
2019-10-04 16:37:34,009 [salt.utils.schedule:686 ][DEBUG   ][5971] schedule.handle_func: adding this job to the jobcache with data {u'fun_args': [], u'jid': u'20191004163734008707', u'schedule': u'__mine_interval', u'pid': 5971, u'fun': u'mine.update', u'id': u'ussc-tst-worker-vm1'}
2019-10-04 16:37:34,011 [salt.utils.lazy  :104 ][DEBUG   ][5971] LazyLoaded mine.update
2019-10-04 16:37:34,012 [salt.utils.lazy  :104 ][DEBUG   ][5971] LazyLoaded config.merge
2019-10-04 16:37:34,014 [salt.utils.lazy  :104 ][DEBUG   ][5971] LazyLoaded network.ip_addrs
2019-10-04 16:37:34,032 [salt.loaded.int.module.mine:55  ][ERROR   ][5971] Function host in mine_functions not available
2019-10-04 16:37:34,033 [salt.utils.event :323 ][DEBUG   ][5971] MinionEvent PUB socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pub.ipc
2019-10-04 16:37:34,033 [salt.utils.event :324 ][DEBUG   ][5971] MinionEvent PULL socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pull.ipc
2019-10-04 16:37:34,034 [salt.utils.event :738 ][DEBUG   ][5971] Sending event: tag = _minion_mine; data = {u'clear': False, u'cmd': u'_mine', u'data': {'network.ip_addrs': [u'10.150.145.12']}, u'id': u'ussc-tst-worker-vm1', u'_stamp': '2019-10-04T16:37:34.034703'}
2019-10-04 16:37:34,036 [salt.minion      :2357][DEBUG   ][5852] Minion of 'prd-ssm.reachcm.com' is handling event tag '_minion_mine'
2019-10-04 16:37:34,036 [salt.transport.zeromq:138 ][DEBUG   ][5852] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:37:34,037 [salt.crypt       :464 ][DEBUG   ][5852] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:37:34,038 [salt.transport.zeromq:209 ][DEBUG   ][5852] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:37:34,038 [salt.transport.zeromq:1189][DEBUG   ][5852] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:37:34,135 [salt.transport.zeromq:233 ][DEBUG   ][5852] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:37:34,536 [salt.transport.ipc:364 ][DEBUG   ][5971] Closing IPCMessageClient instance
2019-10-04 16:37:34,536 [salt.utils.schedule:833 ][DEBUG   ][5971] schedule.handle_func: Removing /var/cache/salt/minion/proc/20191004163734008707
2019-10-04 16:37:34,979 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:2-Schedule-__mine_interval cleaned up
2019-10-04 16:37:36,826 [salt.utils.lazy  :104 ][DEBUG   ][5852] LazyLoaded glob_match.match
2019-10-04 16:37:36,827 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command test.ping with jid 20191004163736806443
2019-10-04 16:37:36,827 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'glob', u'jid': u'20191004163736806443', u'tgt': u'*', u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [], u'fun': u'test.ping'}
2019-10-04 16:37:36,833 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:3-Job-20191004163736806443 added
2019-10-04 16:37:36,837 [salt.pillar      :57  ][DEBUG   ][5978] Determining pillar cache
2019-10-04 16:37:36,838 [salt.transport.zeromq:138 ][DEBUG   ][5978] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:37:36,839 [salt.crypt       :464 ][DEBUG   ][5978] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:37:36,840 [salt.transport.zeromq:209 ][DEBUG   ][5978] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:37:36,841 [salt.transport.zeromq:1189][DEBUG   ][5978] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:37:37,156 [salt.crypt       :200 ][DEBUG   ][5978] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:37:37,156 [salt.crypt       :802 ][DEBUG   ][5978] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:37:37,160 [salt.transport.zeromq:233 ][DEBUG   ][5978] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:37:37,204 [salt.utils.lazy  :104 ][DEBUG   ][5978] LazyLoaded jinja.render
2019-10-04 16:37:37,205 [salt.utils.lazy  :104 ][DEBUG   ][5978] LazyLoaded yaml.render
2019-10-04 16:37:37,206 [salt.minion      :1608][INFO    ][5978] Starting a new job 20191004163736806443 with PID 5978
2019-10-04 16:37:37,208 [salt.utils.lazy  :107 ][DEBUG   ][5978] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:37:37,221 [salt.utils.lazy  :104 ][DEBUG   ][5978] LazyLoaded test.ping
2019-10-04 16:37:37,221 [salt.loaded.int.module.test:124 ][DEBUG   ][5978] test.ping received for minion 'ussc-tst-worker-vm1'
2019-10-04 16:37:37,222 [salt.minion      :806 ][DEBUG   ][5978] Minion return retry timer set to 5 seconds (randomized)
2019-10-04 16:37:37,222 [salt.minion      :1936][INFO    ][5978] Returning information for job: 20191004163736806443
2019-10-04 16:37:37,223 [salt.transport.zeromq:138 ][DEBUG   ][5978] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:37:37,223 [salt.crypt       :464 ][DEBUG   ][5978] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:37:37,224 [salt.transport.zeromq:209 ][DEBUG   ][5978] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:37:37,224 [salt.transport.zeromq:1189][DEBUG   ][5978] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:37:37,326 [salt.transport.zeromq:233 ][DEBUG   ][5978] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:37:37,326 [salt.minion      :1786][DEBUG   ][5978] minion return: {u'fun_args': [], u'jid': u'20191004163736806443', u'return': True, u'retcode': 0, u'success': True, u'fun': u'test.ping'}
2019-10-04 16:37:37,980 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:3-Job-20191004163736806443 cleaned up
2019-10-04 16:37:57,465 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command state.apply with jid 20191004163757444435
2019-10-04 16:37:57,465 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'glob', u'jid': u'20191004163757444435', u'tgt': u'*work*', u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'pip'], u'fun': u'state.apply'}
2019-10-04 16:37:57,472 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:4-Job-20191004163757444435 added
2019-10-04 16:37:57,475 [salt.pillar      :57  ][DEBUG   ][6003] Determining pillar cache
2019-10-04 16:37:57,476 [salt.transport.zeromq:138 ][DEBUG   ][6003] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:37:57,476 [salt.crypt       :464 ][DEBUG   ][6003] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:37:57,477 [salt.transport.zeromq:209 ][DEBUG   ][6003] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:37:57,478 [salt.transport.zeromq:1189][DEBUG   ][6003] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:37:57,780 [salt.crypt       :200 ][DEBUG   ][6003] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:37:57,780 [salt.crypt       :802 ][DEBUG   ][6003] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:37:57,784 [salt.transport.zeromq:233 ][DEBUG   ][6003] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:37:57,825 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded jinja.render
2019-10-04 16:37:57,826 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded yaml.render
2019-10-04 16:37:57,827 [salt.minion      :1608][INFO    ][6003] Starting a new job 20191004163757444435 with PID 6003
2019-10-04 16:37:57,829 [salt.utils.lazy  :107 ][DEBUG   ][6003] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:37:57,831 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded state.apply
2019-10-04 16:37:57,833 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded saltutil.is_running
2019-10-04 16:37:57,834 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded grains.get
2019-10-04 16:37:57,837 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded config.get
2019-10-04 16:37:57,837 [salt.loaded.int.module.config:398 ][DEBUG   ][6003] key: test, ret: _|-
2019-10-04 16:37:57,844 [salt.transport.zeromq:138 ][DEBUG   ][6003] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:37:57,845 [salt.crypt       :464 ][DEBUG   ][6003] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:37:57,845 [salt.transport.zeromq:209 ][DEBUG   ][6003] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:37:57,846 [salt.transport.zeromq:1189][DEBUG   ][6003] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:37:59,003 [salt.state       :736 ][DEBUG   ][6003] Gathering pillar data for state run
2019-10-04 16:37:59,003 [salt.pillar      :57  ][DEBUG   ][6003] Determining pillar cache
2019-10-04 16:37:59,003 [salt.transport.zeromq:138 ][DEBUG   ][6003] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:37:59,004 [salt.crypt       :464 ][DEBUG   ][6003] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:37:59,004 [salt.transport.zeromq:209 ][DEBUG   ][6003] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:37:59,005 [salt.transport.zeromq:1189][DEBUG   ][6003] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:37:59,293 [salt.crypt       :200 ][DEBUG   ][6003] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:37:59,293 [salt.crypt       :802 ][DEBUG   ][6003] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:37:59,296 [salt.transport.zeromq:233 ][DEBUG   ][6003] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:37:59,297 [salt.state       :750 ][DEBUG   ][6003] Finished gathering pillar data for state run
2019-10-04 16:37:59,297 [salt.state       :966 ][INFO    ][6003] Loading fresh modules for state activity
2019-10-04 16:37:59,333 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded jinja.render
2019-10-04 16:37:59,334 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded yaml.render
2019-10-04 16:37:59,389 [salt.fileclient  :1072][DEBUG   ][6003] Could not find file 'salt://pip.sls' in saltenv 'base'
2019-10-04 16:37:59,442 [salt.fileclient  :1093][DEBUG   ][6003] In saltenv 'base', looking at rel_path 'pip/init.sls' to resolve 'salt://pip/init.sls'
2019-10-04 16:37:59,442 [salt.fileclient  :1101][DEBUG   ][6003] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/pip/init.sls' to resolve 'salt://pip/init.sls'
2019-10-04 16:37:59,443 [salt.fileclient  :1121][DEBUG   ][6003] Fetching file from saltenv 'base', ** attempting ** 'salt://pip/init.sls'
2019-10-04 16:37:59,443 [salt.fileclient  :1149][DEBUG   ][6003] No dest file found
2019-10-04 16:37:59,498 [salt.fileclient  :1230][INFO    ][6003] Fetching file from saltenv 'base', ** done ** 'pip/init.sls'
2019-10-04 16:37:59,498 [salt.template    :59  ][DEBUG   ][6003] compile template: /var/cache/salt/minion/files/base/pip/init.sls
2019-10-04 16:37:59,499 [salt.utils.jinja :83  ][DEBUG   ][6003] Jinja search path: [u'/var/cache/salt/minion/files/base']
2019-10-04 16:37:59,505 [salt.transport.zeromq:138 ][DEBUG   ][6003] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:37:59,505 [salt.crypt       :464 ][DEBUG   ][6003] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:37:59,506 [salt.transport.zeromq:209 ][DEBUG   ][6003] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:37:59,507 [salt.transport.zeromq:1189][DEBUG   ][6003] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:37:59,628 [salt.fileclient  :1093][DEBUG   ][6003] In saltenv 'base', looking at rel_path 'pip/map.jinja' to resolve 'salt://pip/map.jinja'
2019-10-04 16:37:59,628 [salt.fileclient  :1101][DEBUG   ][6003] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/pip/map.jinja' to resolve 'salt://pip/map.jinja'
2019-10-04 16:37:59,629 [salt.fileclient  :1121][DEBUG   ][6003] Fetching file from saltenv 'base', ** attempting ** 'salt://pip/map.jinja'
2019-10-04 16:37:59,629 [salt.fileclient  :1149][DEBUG   ][6003] No dest file found
2019-10-04 16:37:59,682 [salt.fileclient  :1230][INFO    ][6003] Fetching file from saltenv 'base', ** done ** 'pip/map.jinja'
2019-10-04 16:37:59,686 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded grains.filter_by
2019-10-04 16:37:59,687 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded pillar.get
2019-10-04 16:37:59,687 [salt.template    :26  ][PROFILE ][6003] Time (in seconds) to render '/var/cache/salt/minion/files/base/pip/init.sls' using 'jinja' renderer: 0.188914060593
2019-10-04 16:37:59,688 [salt.template    :120 ][DEBUG   ][6003] Rendered data from file: /var/cache/salt/minion/files/base/pip/init.sls:


pip:
  pkg.installed:
    - name: python-pip

2019-10-04 16:37:59,688 [salt.loaded.int.render.yaml:80  ][DEBUG   ][6003] Results of YAML rendering: 
OrderedDict([(u'pip', OrderedDict([(u'pkg.installed', [OrderedDict([(u'name', u'python-pip')])])]))])
2019-10-04 16:37:59,689 [salt.template    :26  ][PROFILE ][6003] Time (in seconds) to render '/var/cache/salt/minion/files/base/pip/init.sls' using 'yaml' renderer: 0.000921010971069
2019-10-04 16:37:59,690 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded config.option
2019-10-04 16:37:59,704 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded pkg.install
2019-10-04 16:37:59,704 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded pkg.installed
2019-10-04 16:37:59,858 [salt.loaded.int.module.config:398 ][DEBUG   ][6003] key: ifttt.secret_key, ret: _|-
2019-10-04 16:37:59,858 [salt.loaded.int.module.config:398 ][DEBUG   ][6003] key: ifttt:secret_key, ret: _|-
2019-10-04 16:37:59,988 [salt.loaded.int.module.config:398 ][DEBUG   ][6003] key: pushbullet.api_key, ret: _|-
2019-10-04 16:37:59,989 [salt.loaded.int.module.config:398 ][DEBUG   ][6003] key: pushbullet:api_key, ret: _|-
2019-10-04 16:38:00,011 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded systemd.booted
2019-10-04 16:38:00,074 [salt.loaded.int.module.config:398 ][DEBUG   ][6003] key: victorops.api_key, ret: _|-
2019-10-04 16:38:00,074 [salt.loaded.int.module.config:398 ][DEBUG   ][6003] key: victorops:api_key, ret: _|-
2019-10-04 16:38:00,284 [salt.loaded.int.module.win_dsc:43  ][DEBUG   ][6003] DSC: Only available on Windows systems
2019-10-04 16:38:00,296 [salt.loaded.int.module.win_psget:36  ][DEBUG   ][6003] Module PSGet: Only available on Windows systems
2019-10-04 16:38:00,302 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded platform.is_windows
2019-10-04 16:38:00,357 [salt.utils.lazy  :107 ][DEBUG   ][6003] Could not LazyLoad pkg.ex_mod_init: 'pkg.ex_mod_init' is not available.
2019-10-04 16:38:00,358 [salt.state       :1819][INFO    ][6003] Running state [python-pip] at time 16:38:00.358296
2019-10-04 16:38:00,358 [salt.state       :1852][INFO    ][6003] Executing state pkg.installed for [python-pip]
2019-10-04 16:38:00,368 [salt.utils.lazy  :107 ][DEBUG   ][6003] Could not LazyLoad pkg.resolve_capabilities: 'pkg.resolve_capabilities' is not available.
2019-10-04 16:38:00,369 [salt.loaded.int.module.cmdmod:397 ][INFO    ][6003] Executing command [u'dpkg-query', u'--showformat', u'${Status} ${Package} ${Version} ${Architecture}', u'-W'] in directory '/root'
2019-10-04 16:38:00,406 [salt.utils.lazy  :107 ][DEBUG   ][6003] Could not LazyLoad pkg.normalize_name: 'pkg.normalize_name' is not available.
2019-10-04 16:38:00,415 [salt.utils.lazy  :107 ][DEBUG   ][6003] Could not LazyLoad pkg.check_db: 'pkg.check_db' is not available.
2019-10-04 16:38:00,416 [salt.loaded.int.module.cmdmod:397 ][INFO    ][6003] Executing command [u'apt-cache', u'-q', u'policy', u'python-pip'] in directory '/root'
2019-10-04 16:38:00,568 [salt.utils.lazy  :107 ][DEBUG   ][6003] Could not LazyLoad pkg.normalize_name: 'pkg.normalize_name' is not available.
2019-10-04 16:38:00,569 [salt.loaded.int.module.cmdmod:397 ][INFO    ][6003] Executing command [u'apt-get', u'-q', u'update'] in directory '/root'
2019-10-04 16:38:02,299 [salt.loaded.int.module.cmdmod:397 ][INFO    ][6003] Executing command [u'dpkg', u'--get-selections', u'*'] in directory '/root'
2019-10-04 16:38:02,331 [salt.loaded.int.module.config:398 ][DEBUG   ][6003] key: systemd.scope, ret: _|-
2019-10-04 16:38:02,331 [salt.loaded.int.module.cmdmod:397 ][INFO    ][6003] Executing command [u'systemd-run', u'--scope', u'apt-get', u'-q', u'-y', u'-o', u'DPkg::Options::=--force-confold', u'-o', u'DPkg::Options::=--force-confdef', u'install', u'python-pip'] in directory '/root'
2019-10-04 16:38:02,510 [salt.utils.lazy  :104 ][DEBUG   ][5852] LazyLoaded list_match.match
2019-10-04 16:38:02,512 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command saltutil.find_job with jid 20191004163802489388
2019-10-04 16:38:02,512 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'list', u'jid': u'20191004163802489388', u'tgt': [u'ussc-tst-worker-vm1'], u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'20191004163757444435'], u'fun': u'saltutil.find_job'}
2019-10-04 16:38:02,519 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:5-Job-20191004163802489388 added
2019-10-04 16:38:02,527 [salt.pillar      :57  ][DEBUG   ][6373] Determining pillar cache
2019-10-04 16:38:02,528 [salt.transport.zeromq:138 ][DEBUG   ][6373] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:02,529 [salt.crypt       :464 ][DEBUG   ][6373] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:02,530 [salt.transport.zeromq:209 ][DEBUG   ][6373] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:02,531 [salt.transport.zeromq:1189][DEBUG   ][6373] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:02,866 [salt.crypt       :200 ][DEBUG   ][6373] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:38:02,866 [salt.crypt       :802 ][DEBUG   ][6373] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:38:02,870 [salt.transport.zeromq:233 ][DEBUG   ][6373] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:02,912 [salt.utils.lazy  :104 ][DEBUG   ][6373] LazyLoaded jinja.render
2019-10-04 16:38:02,913 [salt.utils.lazy  :104 ][DEBUG   ][6373] LazyLoaded yaml.render
2019-10-04 16:38:02,915 [salt.minion      :1608][INFO    ][6373] Starting a new job 20191004163802489388 with PID 6373
2019-10-04 16:38:02,916 [salt.utils.lazy  :107 ][DEBUG   ][6373] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:38:02,918 [salt.utils.lazy  :104 ][DEBUG   ][6373] LazyLoaded saltutil.find_job
2019-10-04 16:38:02,919 [salt.minion      :806 ][DEBUG   ][6373] Minion return retry timer set to 5 seconds (randomized)
2019-10-04 16:38:02,920 [salt.minion      :1936][INFO    ][6373] Returning information for job: 20191004163802489388
2019-10-04 16:38:02,920 [salt.transport.zeromq:138 ][DEBUG   ][6373] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:02,920 [salt.crypt       :464 ][DEBUG   ][6373] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:02,921 [salt.transport.zeromq:209 ][DEBUG   ][6373] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:02,922 [salt.transport.zeromq:1189][DEBUG   ][6373] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:03,016 [salt.transport.zeromq:233 ][DEBUG   ][6373] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:03,017 [salt.minion      :1786][DEBUG   ][6373] minion return: {u'fun_args': [u'20191004163757444435'], u'jid': u'20191004163802489388', u'return': {'tgt_type': 'glob', 'jid': '20191004163757444435', 'tgt': '*work*', 'pid': 6003, 'ret': '', 'user': 'sudo_gjohnson', 'arg': ['pip'], 'fun': 'state.apply'}, u'retcode': 0, u'success': True, u'fun': u'saltutil.find_job'}
2019-10-04 16:38:03,979 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:5-Job-20191004163802489388 cleaned up
2019-10-04 16:38:12,530 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command saltutil.find_job with jid 20191004163812509933
2019-10-04 16:38:12,530 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'list', u'jid': u'20191004163812509933', u'tgt': [u'ussc-tst-worker-vm1'], u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'20191004163757444435'], u'fun': u'saltutil.find_job'}
2019-10-04 16:38:12,541 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:6-Job-20191004163812509933 added
2019-10-04 16:38:12,543 [salt.pillar      :57  ][DEBUG   ][6527] Determining pillar cache
2019-10-04 16:38:12,544 [salt.transport.zeromq:138 ][DEBUG   ][6527] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:12,545 [salt.crypt       :464 ][DEBUG   ][6527] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:12,546 [salt.transport.zeromq:209 ][DEBUG   ][6527] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:12,547 [salt.transport.zeromq:1189][DEBUG   ][6527] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:12,884 [salt.crypt       :200 ][DEBUG   ][6527] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:38:12,884 [salt.crypt       :802 ][DEBUG   ][6527] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:38:12,888 [salt.transport.zeromq:233 ][DEBUG   ][6527] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:12,940 [salt.utils.lazy  :104 ][DEBUG   ][6527] LazyLoaded jinja.render
2019-10-04 16:38:12,941 [salt.utils.lazy  :104 ][DEBUG   ][6527] LazyLoaded yaml.render
2019-10-04 16:38:12,943 [salt.minion      :1608][INFO    ][6527] Starting a new job 20191004163812509933 with PID 6527
2019-10-04 16:38:12,945 [salt.utils.lazy  :107 ][DEBUG   ][6527] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:38:12,947 [salt.utils.lazy  :104 ][DEBUG   ][6527] LazyLoaded saltutil.find_job
2019-10-04 16:38:12,948 [salt.minion      :806 ][DEBUG   ][6527] Minion return retry timer set to 6 seconds (randomized)
2019-10-04 16:38:12,949 [salt.minion      :1936][INFO    ][6527] Returning information for job: 20191004163812509933
2019-10-04 16:38:12,949 [salt.transport.zeromq:138 ][DEBUG   ][6527] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:12,949 [salt.crypt       :464 ][DEBUG   ][6527] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:12,951 [salt.transport.zeromq:209 ][DEBUG   ][6527] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:12,951 [salt.transport.zeromq:1189][DEBUG   ][6527] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:13,051 [salt.transport.zeromq:233 ][DEBUG   ][6527] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:13,052 [salt.minion      :1786][DEBUG   ][6527] minion return: {u'fun_args': [u'20191004163757444435'], u'jid': u'20191004163812509933', u'return': {'tgt_type': 'glob', 'jid': '20191004163757444435', 'tgt': '*work*', 'pid': 6003, 'ret': '', 'user': 'sudo_gjohnson', 'arg': ['pip'], 'fun': 'state.apply'}, u'retcode': 0, u'success': True, u'fun': u'saltutil.find_job'}
2019-10-04 16:38:13,979 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:6-Job-20191004163812509933 cleaned up
2019-10-04 16:38:22,564 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command saltutil.find_job with jid 20191004163822544277
2019-10-04 16:38:22,564 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'list', u'jid': u'20191004163822544277', u'tgt': [u'ussc-tst-worker-vm1'], u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'20191004163757444435'], u'fun': u'saltutil.find_job'}
2019-10-04 16:38:22,571 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:7-Job-20191004163822544277 added
2019-10-04 16:38:22,574 [salt.pillar      :57  ][DEBUG   ][6813] Determining pillar cache
2019-10-04 16:38:22,575 [salt.transport.zeromq:138 ][DEBUG   ][6813] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:22,576 [salt.crypt       :464 ][DEBUG   ][6813] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:22,577 [salt.transport.zeromq:209 ][DEBUG   ][6813] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:22,578 [salt.transport.zeromq:1189][DEBUG   ][6813] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:22,872 [salt.crypt       :200 ][DEBUG   ][6813] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:38:22,873 [salt.crypt       :802 ][DEBUG   ][6813] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:38:22,877 [salt.transport.zeromq:233 ][DEBUG   ][6813] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:22,948 [salt.utils.lazy  :104 ][DEBUG   ][6813] LazyLoaded jinja.render
2019-10-04 16:38:22,949 [salt.utils.lazy  :104 ][DEBUG   ][6813] LazyLoaded yaml.render
2019-10-04 16:38:22,952 [salt.minion      :1608][INFO    ][6813] Starting a new job 20191004163822544277 with PID 6813
2019-10-04 16:38:22,954 [salt.utils.lazy  :107 ][DEBUG   ][6813] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:38:22,957 [salt.utils.lazy  :104 ][DEBUG   ][6813] LazyLoaded saltutil.find_job
2019-10-04 16:38:22,959 [salt.minion      :806 ][DEBUG   ][6813] Minion return retry timer set to 10 seconds (randomized)
2019-10-04 16:38:22,959 [salt.minion      :1936][INFO    ][6813] Returning information for job: 20191004163822544277
2019-10-04 16:38:22,960 [salt.transport.zeromq:138 ][DEBUG   ][6813] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:22,960 [salt.crypt       :464 ][DEBUG   ][6813] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:22,961 [salt.transport.zeromq:209 ][DEBUG   ][6813] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:22,962 [salt.transport.zeromq:1189][DEBUG   ][6813] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:23,062 [salt.transport.zeromq:233 ][DEBUG   ][6813] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:23,063 [salt.minion      :1786][DEBUG   ][6813] minion return: {u'fun_args': [u'20191004163757444435'], u'jid': u'20191004163822544277', u'return': {'tgt_type': 'glob', 'jid': '20191004163757444435', 'tgt': '*work*', 'pid': 6003, 'ret': '', 'user': 'sudo_gjohnson', 'arg': ['pip'], 'fun': 'state.apply'}, u'retcode': 0, u'success': True, u'fun': u'saltutil.find_job'}
2019-10-04 16:38:23,980 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:7-Job-20191004163822544277 cleaned up
2019-10-04 16:38:32,575 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command saltutil.find_job with jid 20191004163832555664
2019-10-04 16:38:32,576 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'list', u'jid': u'20191004163832555664', u'tgt': [u'ussc-tst-worker-vm1'], u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'20191004163757444435'], u'fun': u'saltutil.find_job'}
2019-10-04 16:38:32,583 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:8-Job-20191004163832555664 added
2019-10-04 16:38:32,586 [salt.pillar      :57  ][DEBUG   ][7033] Determining pillar cache
2019-10-04 16:38:32,587 [salt.transport.zeromq:138 ][DEBUG   ][7033] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:32,588 [salt.crypt       :464 ][DEBUG   ][7033] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:32,589 [salt.transport.zeromq:209 ][DEBUG   ][7033] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:32,590 [salt.transport.zeromq:1189][DEBUG   ][7033] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:32,882 [salt.crypt       :200 ][DEBUG   ][7033] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:38:32,882 [salt.crypt       :802 ][DEBUG   ][7033] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:38:32,886 [salt.transport.zeromq:233 ][DEBUG   ][7033] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:32,929 [salt.utils.lazy  :104 ][DEBUG   ][7033] LazyLoaded jinja.render
2019-10-04 16:38:32,930 [salt.utils.lazy  :104 ][DEBUG   ][7033] LazyLoaded yaml.render
2019-10-04 16:38:32,932 [salt.minion      :1608][INFO    ][7033] Starting a new job 20191004163832555664 with PID 7033
2019-10-04 16:38:32,933 [salt.utils.lazy  :107 ][DEBUG   ][7033] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:38:32,935 [salt.utils.lazy  :104 ][DEBUG   ][7033] LazyLoaded saltutil.find_job
2019-10-04 16:38:32,937 [salt.minion      :806 ][DEBUG   ][7033] Minion return retry timer set to 8 seconds (randomized)
2019-10-04 16:38:32,937 [salt.minion      :1936][INFO    ][7033] Returning information for job: 20191004163832555664
2019-10-04 16:38:32,937 [salt.transport.zeromq:138 ][DEBUG   ][7033] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:32,938 [salt.crypt       :464 ][DEBUG   ][7033] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:32,938 [salt.transport.zeromq:209 ][DEBUG   ][7033] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:32,939 [salt.transport.zeromq:1189][DEBUG   ][7033] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:33,032 [salt.transport.zeromq:233 ][DEBUG   ][7033] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:33,033 [salt.minion      :1786][DEBUG   ][7033] minion return: {u'fun_args': [u'20191004163757444435'], u'jid': u'20191004163832555664', u'return': {'tgt_type': 'glob', 'jid': '20191004163757444435', 'tgt': '*work*', 'pid': 6003, 'ret': '', 'user': 'sudo_gjohnson', 'arg': ['pip'], 'fun': 'state.apply'}, u'retcode': 0, u'success': True, u'fun': u'saltutil.find_job'}
2019-10-04 16:38:33,979 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:8-Job-20191004163832555664 cleaned up
2019-10-04 16:38:42,764 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command saltutil.find_job with jid 20191004163842742611
2019-10-04 16:38:42,764 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'list', u'jid': u'20191004163842742611', u'tgt': [u'ussc-tst-worker-vm1'], u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'20191004163757444435'], u'fun': u'saltutil.find_job'}
2019-10-04 16:38:42,771 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:9-Job-20191004163842742611 added
2019-10-04 16:38:42,776 [salt.pillar      :57  ][DEBUG   ][8712] Determining pillar cache
2019-10-04 16:38:42,777 [salt.transport.zeromq:138 ][DEBUG   ][8712] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:42,778 [salt.crypt       :464 ][DEBUG   ][8712] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:42,783 [salt.transport.zeromq:209 ][DEBUG   ][8712] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:42,784 [salt.transport.zeromq:1189][DEBUG   ][8712] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:43,095 [salt.crypt       :200 ][DEBUG   ][8712] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:38:43,095 [salt.crypt       :802 ][DEBUG   ][8712] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:38:43,100 [salt.transport.zeromq:233 ][DEBUG   ][8712] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:43,189 [salt.utils.lazy  :104 ][DEBUG   ][8712] LazyLoaded jinja.render
2019-10-04 16:38:43,191 [salt.utils.lazy  :104 ][DEBUG   ][8712] LazyLoaded yaml.render
2019-10-04 16:38:43,193 [salt.minion      :1608][INFO    ][8712] Starting a new job 20191004163842742611 with PID 8712
2019-10-04 16:38:43,196 [salt.utils.lazy  :107 ][DEBUG   ][8712] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:38:43,198 [salt.utils.lazy  :104 ][DEBUG   ][8712] LazyLoaded saltutil.find_job
2019-10-04 16:38:43,200 [salt.minion      :806 ][DEBUG   ][8712] Minion return retry timer set to 5 seconds (randomized)
2019-10-04 16:38:43,201 [salt.minion      :1936][INFO    ][8712] Returning information for job: 20191004163842742611
2019-10-04 16:38:43,201 [salt.transport.zeromq:138 ][DEBUG   ][8712] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:43,202 [salt.crypt       :464 ][DEBUG   ][8712] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:43,203 [salt.transport.zeromq:209 ][DEBUG   ][8712] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:43,203 [salt.transport.zeromq:1189][DEBUG   ][8712] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:43,306 [salt.transport.zeromq:233 ][DEBUG   ][8712] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:43,307 [salt.minion      :1786][DEBUG   ][8712] minion return: {u'fun_args': [u'20191004163757444435'], u'jid': u'20191004163842742611', u'return': {'tgt_type': 'glob', 'jid': '20191004163757444435', 'tgt': '*work*', 'pid': 6003, 'ret': '', 'user': 'sudo_gjohnson', 'arg': ['pip'], 'fun': 'state.apply'}, u'retcode': 0, u'success': True, u'fun': u'saltutil.find_job'}
2019-10-04 16:38:43,981 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:9-Job-20191004163842742611 cleaned up
2019-10-04 16:38:52,775 [salt.loaded.int.module.cmdmod:397 ][INFO    ][6003] Executing command [u'dpkg-query', u'--showformat', u'${Status} ${Package} ${Version} ${Architecture}', u'-W'] in directory '/root'
2019-10-04 16:38:52,818 [salt.state       :320 ][INFO    ][6003] Made the following changes:
'build-essential' changed from 'absent' to '12.4ubuntu1'
'python-all-dev' changed from 'absent' to '2.7.15~rc1-1'
'python-xdg' changed from 'absent' to '0.25-4ubuntu1'
'libpython-all-dev' changed from 'absent' to '2.7.15~rc1-1'
'libgomp1' changed from 'absent' to '8.3.0-6ubuntu1~18.04.1'
'libpython-dev' changed from 'absent' to '2.7.15~rc1-1'
'libalgorithm-merge-perl' changed from 'absent' to '0.08-3'
'python2.7-dev' changed from 'absent' to '2.7.15-4ubuntu4~18.04.1'
'python-wheel' changed from 'absent' to '0.30.0-0.2'
'libfakeroot' changed from 'absent' to '1.22-2ubuntu1'
'linux-libc-dev' changed from 'absent' to '4.15.0-65.74'
'gcc-7' changed from 'absent' to '7.4.0-1ubuntu1~18.04.1'
'python-secretstorage' changed from 'absent' to '2.3.1-2'
'python-pip-whl' changed from 'absent' to '9.0.1-2.3~ubuntu1.18.04.1'
'python-dev' changed from 'absent' to '2.7.15~rc1-1'
'libubsan0' changed from 'absent' to '7.4.0-1ubuntu1~18.04.1'
'libalgorithm-diff-xs-perl' changed from 'absent' to '0.04-5'
'gcc' changed from 'absent' to '4:7.4.0-1ubuntu2.3'
'libbinutils' changed from 'absent' to '2.30-21ubuntu1~18.04.2'
'binutils-x86-64-linux-gnu' changed from 'absent' to '2.30-21ubuntu1~18.04.2'
'make' changed from 'absent' to '4.1-9.1ubuntu1'
'libitm1' changed from 'absent' to '8.3.0-6ubuntu1~18.04.1'
'g++' changed from 'absent' to '4:7.4.0-1ubuntu2.3'
'libfile-fcntllock-perl' changed from 'absent' to '0.22-3build2'
'libquadmath0' changed from 'absent' to '8.3.0-6ubuntu1~18.04.1'
'python-gi' changed from 'absent' to '3.26.1-2ubuntu1'
'python-keyrings.alt' changed from 'absent' to '3.0-1'
'dpkg-dev' changed from 'absent' to '1.19.0.5ubuntu2.3'
'libmpx2' changed from 'absent' to '8.3.0-6ubuntu1~18.04.1'
'python-setuptools' changed from 'absent' to '39.0.1-2'
'binutils-common' changed from 'absent' to '2.30-21ubuntu1~18.04.2'
'python-all' changed from 'absent' to '2.7.15~rc1-1'
'libatomic1' changed from 'absent' to '8.3.0-6ubuntu1~18.04.1'
'g++-7' changed from 'absent' to '7.4.0-1ubuntu1~18.04.1'
'libtsan0' changed from 'absent' to '8.3.0-6ubuntu1~18.04.1'
'python-dbus' changed from 'absent' to '1.2.6-1'
'libmpc3' changed from 'absent' to '1.1.0-1'
'libasan4' changed from 'absent' to '7.4.0-1ubuntu1~18.04.1'
'libgcc-7-dev' changed from 'absent' to '7.4.0-1ubuntu1~18.04.1'
'libc6-dev' changed from 'absent' to '2.27-3ubuntu1'
'libdpkg-perl' changed from 'absent' to '1.19.0.5ubuntu2.3'
'libcilkrts5' changed from 'absent' to '7.4.0-1ubuntu1~18.04.1'
'gcc-7-base' changed from 'absent' to '7.4.0-1ubuntu1~18.04.1'
'libstdc++-7-dev' changed from 'absent' to '7.4.0-1ubuntu1~18.04.1'
'manpages-dev' changed from 'absent' to '4.15-1'
'libcc1-0' changed from 'absent' to '8.3.0-6ubuntu1~18.04.1'
'libisl19' changed from 'absent' to '0.19-1'
'cpp-7' changed from 'absent' to '7.4.0-1ubuntu1~18.04.1'
'python-pip' changed from 'absent' to '9.0.1-2.3~ubuntu1.18.04.1'
'libalgorithm-diff-perl' changed from 'absent' to '1.19.03-1'
'libpython2.7-dev' changed from 'absent' to '2.7.15-4ubuntu4~18.04.1'
'liblsan0' changed from 'absent' to '8.3.0-6ubuntu1~18.04.1'
'fakeroot' changed from 'absent' to '1.22-2ubuntu1'
'libexpat1-dev' changed from 'absent' to '2.2.5-3ubuntu0.2'
'libc-dev-bin' changed from 'absent' to '2.27-3ubuntu1'
'cpp' changed from 'absent' to '4:7.4.0-1ubuntu2.3'
'libexpat1' changed from '2.2.5-3ubuntu0.1' to '2.2.5-3ubuntu0.2'
'python-keyring' changed from 'absent' to '10.6.0-1'
'binutils' changed from 'absent' to '2.30-21ubuntu1~18.04.2'

2019-10-04 16:38:52,819 [salt.state       :1000][DEBUG   ][6003] Refreshing modules...
2019-10-04 16:38:52,824 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command saltutil.find_job with jid 20191004163852801129
2019-10-04 16:38:52,825 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'list', u'jid': u'20191004163852801129', u'tgt': [u'ussc-tst-worker-vm1'], u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'20191004163757444435'], u'fun': u'saltutil.find_job'}
2019-10-04 16:38:52,831 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:10-Job-20191004163852801129 added
2019-10-04 16:38:52,838 [salt.pillar      :57  ][DEBUG   ][11736] Determining pillar cache
2019-10-04 16:38:52,840 [salt.transport.zeromq:138 ][DEBUG   ][11736] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:52,841 [salt.crypt       :464 ][DEBUG   ][11736] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:52,842 [salt.transport.zeromq:209 ][DEBUG   ][11736] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:52,843 [salt.transport.zeromq:1189][DEBUG   ][11736] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:52,846 [salt.state       :966 ][INFO    ][6003] Loading fresh modules for state activity
2019-10-04 16:38:52,882 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded jinja.render
2019-10-04 16:38:52,883 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded yaml.render
2019-10-04 16:38:52,886 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded saltutil.refresh_modules
2019-10-04 16:38:52,887 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded event.fire
2019-10-04 16:38:52,887 [salt.utils.event :323 ][DEBUG   ][6003] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pub.ipc
2019-10-04 16:38:52,887 [salt.utils.event :324 ][DEBUG   ][6003] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pull.ipc
2019-10-04 16:38:52,889 [salt.utils.event :738 ][DEBUG   ][6003] Sending event: tag = module_refresh; data = {u'_stamp': '2019-10-04T16:38:52.889311'}
2019-10-04 16:38:52,890 [salt.transport.ipc:364 ][DEBUG   ][6003] Closing IPCMessageClient instance
2019-10-04 16:38:52,890 [salt.state       :1997][INFO    ][6003] Completed state [python-pip] at time 16:38:52.890540 (duration_in_ms=52532.243)
2019-10-04 16:38:52,891 [salt.state       :2801][DEBUG   ][6003] File /var/cache/salt/minion/accumulator/139875882023440 does not exist, no need to cleanup
2019-10-04 16:38:52,892 [salt.utils.lazy  :104 ][DEBUG   ][6003] LazyLoaded state.check_result
2019-10-04 16:38:52,892 [salt.minion      :2357][DEBUG   ][5852] Minion of 'prd-ssm.reachcm.com' is handling event tag 'module_refresh'
2019-10-04 16:38:52,892 [salt.minion      :806 ][DEBUG   ][6003] Minion return retry timer set to 9 seconds (randomized)
2019-10-04 16:38:52,892 [salt.minion      :2160][DEBUG   ][5852] Refreshing modules. Notify=False
2019-10-04 16:38:52,893 [salt.minion      :1936][INFO    ][6003] Returning information for job: 20191004163757444435
2019-10-04 16:38:52,893 [salt.loader      :747 ][DEBUG   ][5852] Grains refresh requested. Refreshing grains.
2019-10-04 16:38:52,894 [salt.config      :2185][DEBUG   ][5852] Reading configuration from /etc/salt/minion
2019-10-04 16:38:52,893 [salt.transport.zeromq:138 ][DEBUG   ][6003] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:52,894 [salt.crypt       :464 ][DEBUG   ][6003] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:52,895 [salt.transport.zeromq:209 ][DEBUG   ][6003] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:52,896 [salt.config      :2329][DEBUG   ][5852] Including configuration from '/etc/salt/minion.d/_schedule.conf'
2019-10-04 16:38:52,896 [salt.transport.zeromq:1189][DEBUG   ][6003] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:52,896 [salt.config      :2185][DEBUG   ][5852] Reading configuration from /etc/salt/minion.d/_schedule.conf
2019-10-04 16:38:53,004 [salt.transport.zeromq:233 ][DEBUG   ][6003] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:53,005 [salt.minion      :1786][DEBUG   ][6003] minion return: {u'fun_args': [u'pip'], u'jid': u'20191004163757444435', u'return': {u'pkg_|-pip_|-python-pip_|-installed': {u'comment': u'The following packages were installed/updated: python-pip', u'name': u'python-pip', u'start_time': '16:38:00.358297', u'result': True, u'duration': 52532.243, u'__run_num__': 0, u'__sls__': u'pip', u'changes': {u'build-essential': {u'new': u'12.4ubuntu1', u'old': u''}, u'python-all-dev': {u'new': u'2.7.15~rc1-1', u'old': u''}, u'python-xdg': {u'new': u'0.25-4ubuntu1', u'old': u''}, u'libpython-all-dev': {u'new': u'2.7.15~rc1-1', u'old': u''}, u'libgomp1': {u'new': u'8.3.0-6ubuntu1~18.04.1', u'old': u''}, u'libpython-dev': {u'new': u'2.7.15~rc1-1', u'old': u''}, u'libalgorithm-merge-perl': {u'new': u'0.08-3', u'old': u''}, u'python2.7-dev': {u'new': u'2.7.15-4ubuntu4~18.04.1', u'old': u''}, u'python-wheel': {u'new': u'0.30.0-0.2', u'old': u''}, u'libfakeroot': {u'new': u'1.22-2ubuntu1', u'old': u''}, u'linux-libc-dev': {u'new': u'4.15.0-65.74', u'old': u''}, u'gcc-7': {u'new': u'7.4.0-1ubuntu1~18.04.1', u'old': u''}, u'python-secretstorage': {u'new': u'2.3.1-2', u'old': u''}, u'python-pip-whl': {u'new': u'9.0.1-2.3~ubuntu1.18.04.1', u'old': u''}, u'python-dev': {u'new': u'2.7.15~rc1-1', u'old': u''}, u'libubsan0': {u'new': u'7.4.0-1ubuntu1~18.04.1', u'old': u''}, u'libalgorithm-diff-xs-perl': {u'new': u'0.04-5', u'old': u''}, u'gcc': {u'new': u'4:7.4.0-1ubuntu2.3', u'old': u''}, u'libbinutils': {u'new': u'2.30-21ubuntu1~18.04.2', u'old': u''}, u'binutils-x86-64-linux-gnu': {u'new': u'2.30-21ubuntu1~18.04.2', u'old': u''}, u'make': {u'new': u'4.1-9.1ubuntu1', u'old': u''}, u'libitm1': {u'new': u'8.3.0-6ubuntu1~18.04.1', u'old': u''}, u'g++': {u'new': u'4:7.4.0-1ubuntu2.3', u'old': u''}, u'libfile-fcntllock-perl': {u'new': u'0.22-3build2', u'old': u''}, u'libquadmath0': {u'new': u'8.3.0-6ubuntu1~18.04.1', u'old': u''}, u'python-gi': {u'new': u'3.26.1-2ubuntu1', u'old': u''}, u'python-keyrings.alt': {u'new': u'3.0-1', u'old': u''}, u'dpkg-dev': {u'new': u'1.19.0.5ubuntu2.3', u'old': u''}, u'libmpx2': {u'new': u'8.3.0-6ubuntu1~18.04.1', u'old': u''}, u'python-setuptools': {u'new': u'39.0.1-2', u'old': u''}, u'binutils-common': {u'new': u'2.30-21ubuntu1~18.04.2', u'old': u''}, u'python-all': {u'new': u'2.7.15~rc1-1', u'old': u''}, u'libatomic1': {u'new': u'8.3.0-6ubuntu1~18.04.1', u'old': u''}, u'g++-7': {u'new': u'7.4.0-1ubuntu1~18.04.1', u'old': u''}, u'libtsan0': {u'new': u'8.3.0-6ubuntu1~18.04.1', u'old': u''}, u'python-dbus': {u'new': u'1.2.6-1', u'old': u''}, u'libmpc3': {u'new': u'1.1.0-1', u'old': u''}, u'libasan4': {u'new': u'7.4.0-1ubuntu1~18.04.1', u'old': u''}, u'libgcc-7-dev': {u'new': u'7.4.0-1ubuntu1~18.04.1', u'old': u''}, u'libc6-dev': {u'new': u'2.27-3ubuntu1', u'old': u''}, u'libdpkg-perl': {u'new': u'1.19.0.5ubuntu2.3', u'old': u''}, u'libcilkrts5': {u'new': u'7.4.0-1ubuntu1~18.04.1', u'old': u''}, u'gcc-7-base': {u'new': u'7.4.0-1ubuntu1~18.04.1', u'old': u''}, u'libstdc++-7-dev': {u'new': u'7.4.0-1ubuntu1~18.04.1', u'old': u''}, u'manpages-dev': {u'new': u'4.15-1', u'old': u''}, u'libcc1-0': {u'new': u'8.3.0-6ubuntu1~18.04.1', u'old': u''}, u'libisl19': {u'new': u'0.19-1', u'old': u''}, u'cpp-7': {u'new': u'7.4.0-1ubuntu1~18.04.1', u'old': u''}, u'python-pip': {u'new': u'9.0.1-2.3~ubuntu1.18.04.1', u'old': u''}, u'libalgorithm-diff-perl': {u'new': u'1.19.03-1', u'old': u''}, u'libpython2.7-dev': {u'new': u'2.7.15-4ubuntu4~18.04.1', u'old': u''}, u'liblsan0': {u'new': u'8.3.0-6ubuntu1~18.04.1', u'old': u''}, u'fakeroot': {u'new': u'1.22-2ubuntu1', u'old': u''}, u'libexpat1-dev': {u'new': u'2.2.5-3ubuntu0.2', u'old': u''}, u'libc-dev-bin': {u'new': u'2.27-3ubuntu1', u'old': u''}, u'cpp': {u'new': u'4:7.4.0-1ubuntu2.3', u'old': u''}, u'libexpat1': {u'new': u'2.2.5-3ubuntu0.2', u'old': u'2.2.5-3ubuntu0.1'}, u'python-keyring': {u'new': u'10.6.0-1', u'old': u''}, u'binutils': {u'new': u'2.30-21ubuntu1~18.04.2', u'old': u''}}, u'__id__': u'pip'}}, u'retcode': 0, u'success': True, u'fun': u'state.apply'}
2019-10-04 16:38:53,134 [salt.utils.lazy  :104 ][DEBUG   ][5852] LazyLoaded config.merge
2019-10-04 16:38:53,135 [salt.utils.lazy  :104 ][DEBUG   ][5852] LazyLoaded mine.update
2019-10-04 16:38:53,136 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:4-Job-20191004163757444435 cleaned up
2019-10-04 16:38:53,176 [salt.crypt       :200 ][DEBUG   ][11736] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:38:53,176 [salt.crypt       :802 ][DEBUG   ][11736] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:38:53,180 [salt.transport.zeromq:233 ][DEBUG   ][11736] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:53,221 [salt.utils.lazy  :104 ][DEBUG   ][11736] LazyLoaded jinja.render
2019-10-04 16:38:53,222 [salt.utils.lazy  :104 ][DEBUG   ][11736] LazyLoaded yaml.render
2019-10-04 16:38:53,224 [salt.minion      :1608][INFO    ][11736] Starting a new job 20191004163852801129 with PID 11736
2019-10-04 16:38:53,226 [salt.utils.lazy  :107 ][DEBUG   ][11736] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:38:53,228 [salt.utils.lazy  :104 ][DEBUG   ][11736] LazyLoaded saltutil.find_job
2019-10-04 16:38:53,229 [salt.minion      :806 ][DEBUG   ][11736] Minion return retry timer set to 10 seconds (randomized)
2019-10-04 16:38:53,230 [salt.minion      :1936][INFO    ][11736] Returning information for job: 20191004163852801129
2019-10-04 16:38:53,230 [salt.transport.zeromq:138 ][DEBUG   ][11736] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:38:53,231 [salt.crypt       :464 ][DEBUG   ][11736] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:38:53,232 [salt.transport.zeromq:209 ][DEBUG   ][11736] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:38:53,232 [salt.transport.zeromq:1189][DEBUG   ][11736] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:38:53,328 [salt.transport.zeromq:233 ][DEBUG   ][11736] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:38:53,329 [salt.minion      :1786][DEBUG   ][11736] minion return: {u'fun_args': [u'20191004163757444435'], u'jid': u'20191004163852801129', u'return': {}, u'retcode': 0, u'success': True, u'fun': u'saltutil.find_job'}
2019-10-04 16:38:53,979 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:10-Job-20191004163852801129 cleaned up
2019-10-04 16:38:59,994 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command state.apply with jid 20191004163859974556
2019-10-04 16:38:59,994 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'glob', u'jid': u'20191004163859974556', u'tgt': u'*work*', u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'php'], u'fun': u'state.apply'}
2019-10-04 16:39:00,001 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:11-Job-20191004163859974556 added
2019-10-04 16:39:00,004 [salt.pillar      :57  ][DEBUG   ][11769] Determining pillar cache
2019-10-04 16:39:00,005 [salt.transport.zeromq:138 ][DEBUG   ][11769] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:00,006 [salt.crypt       :464 ][DEBUG   ][11769] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:00,007 [salt.transport.zeromq:209 ][DEBUG   ][11769] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:00,008 [salt.transport.zeromq:1189][DEBUG   ][11769] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:00,302 [salt.crypt       :200 ][DEBUG   ][11769] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:39:00,302 [salt.crypt       :802 ][DEBUG   ][11769] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:39:00,306 [salt.transport.zeromq:233 ][DEBUG   ][11769] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:00,351 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded jinja.render
2019-10-04 16:39:00,353 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded yaml.render
2019-10-04 16:39:00,354 [salt.minion      :1608][INFO    ][11769] Starting a new job 20191004163859974556 with PID 11769
2019-10-04 16:39:00,356 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:39:00,358 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded state.apply
2019-10-04 16:39:00,360 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded saltutil.is_running
2019-10-04 16:39:00,362 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded grains.get
2019-10-04 16:39:00,364 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded config.get
2019-10-04 16:39:00,365 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: test, ret: _|-
2019-10-04 16:39:00,371 [salt.transport.zeromq:138 ][DEBUG   ][11769] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:00,371 [salt.crypt       :464 ][DEBUG   ][11769] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:00,372 [salt.transport.zeromq:209 ][DEBUG   ][11769] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:00,372 [salt.transport.zeromq:1189][DEBUG   ][11769] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:01,526 [salt.state       :736 ][DEBUG   ][11769] Gathering pillar data for state run
2019-10-04 16:39:01,526 [salt.pillar      :57  ][DEBUG   ][11769] Determining pillar cache
2019-10-04 16:39:01,526 [salt.transport.zeromq:138 ][DEBUG   ][11769] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:01,527 [salt.crypt       :464 ][DEBUG   ][11769] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:01,528 [salt.transport.zeromq:209 ][DEBUG   ][11769] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:01,528 [salt.transport.zeromq:1189][DEBUG   ][11769] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:01,818 [salt.crypt       :200 ][DEBUG   ][11769] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:39:01,818 [salt.crypt       :802 ][DEBUG   ][11769] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:39:01,822 [salt.transport.zeromq:233 ][DEBUG   ][11769] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:01,823 [salt.state       :750 ][DEBUG   ][11769] Finished gathering pillar data for state run
2019-10-04 16:39:01,823 [salt.state       :966 ][INFO    ][11769] Loading fresh modules for state activity
2019-10-04 16:39:01,860 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded jinja.render
2019-10-04 16:39:01,861 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded yaml.render
2019-10-04 16:39:01,916 [salt.fileclient  :1072][DEBUG   ][11769] Could not find file 'salt://php.sls' in saltenv 'base'
2019-10-04 16:39:01,968 [salt.fileclient  :1093][DEBUG   ][11769] In saltenv 'base', looking at rel_path 'php/init.sls' to resolve 'salt://php/init.sls'
2019-10-04 16:39:01,969 [salt.fileclient  :1101][DEBUG   ][11769] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/php/init.sls' to resolve 'salt://php/init.sls'
2019-10-04 16:39:01,969 [salt.fileclient  :1121][DEBUG   ][11769] Fetching file from saltenv 'base', ** attempting ** 'salt://php/init.sls'
2019-10-04 16:39:01,969 [salt.fileclient  :1149][DEBUG   ][11769] No dest file found
2019-10-04 16:39:02,022 [salt.fileclient  :1230][INFO    ][11769] Fetching file from saltenv 'base', ** done ** 'php/init.sls'
2019-10-04 16:39:02,023 [salt.template    :59  ][DEBUG   ][11769] compile template: /var/cache/salt/minion/files/base/php/init.sls
2019-10-04 16:39:02,023 [salt.utils.jinja :83  ][DEBUG   ][11769] Jinja search path: [u'/var/cache/salt/minion/files/base']
2019-10-04 16:39:02,029 [salt.transport.zeromq:138 ][DEBUG   ][11769] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:02,030 [salt.crypt       :464 ][DEBUG   ][11769] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:02,030 [salt.transport.zeromq:209 ][DEBUG   ][11769] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:02,031 [salt.transport.zeromq:1189][DEBUG   ][11769] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:02,154 [salt.fileclient  :1093][DEBUG   ][11769] In saltenv 'base', looking at rel_path 'php/installed.jinja' to resolve 'salt://php/installed.jinja'
2019-10-04 16:39:02,154 [salt.fileclient  :1101][DEBUG   ][11769] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/php/installed.jinja' to resolve 'salt://php/installed.jinja'
2019-10-04 16:39:02,155 [salt.fileclient  :1121][DEBUG   ][11769] Fetching file from saltenv 'base', ** attempting ** 'salt://php/installed.jinja'
2019-10-04 16:39:02,155 [salt.fileclient  :1149][DEBUG   ][11769] No dest file found
2019-10-04 16:39:02,208 [salt.fileclient  :1230][INFO    ][11769] Fetching file from saltenv 'base', ** done ** 'php/installed.jinja'
2019-10-04 16:39:02,290 [salt.fileclient  :1093][DEBUG   ][11769] In saltenv 'base', looking at rel_path 'php/map.jinja' to resolve 'salt://php/map.jinja'
2019-10-04 16:39:02,291 [salt.fileclient  :1101][DEBUG   ][11769] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/php/map.jinja' to resolve 'salt://php/map.jinja'
2019-10-04 16:39:02,291 [salt.fileclient  :1121][DEBUG   ][11769] Fetching file from saltenv 'base', ** attempting ** 'salt://php/map.jinja'
2019-10-04 16:39:02,291 [salt.fileclient  :1149][DEBUG   ][11769] No dest file found
2019-10-04 16:39:02,424 [salt.fileclient  :1230][INFO    ][11769] Fetching file from saltenv 'base', ** done ** 'php/map.jinja'
2019-10-04 16:39:02,962 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded pillar.get
2019-10-04 16:39:02,963 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded grains.get
2019-10-04 16:39:03,017 [salt.fileclient  :1093][DEBUG   ][11769] In saltenv 'base', looking at rel_path 'php/macro.jinja' to resolve 'salt://php/macro.jinja'
2019-10-04 16:39:03,017 [salt.fileclient  :1101][DEBUG   ][11769] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/php/macro.jinja' to resolve 'salt://php/macro.jinja'
2019-10-04 16:39:03,018 [salt.fileclient  :1121][DEBUG   ][11769] Fetching file from saltenv 'base', ** attempting ** 'salt://php/macro.jinja'
2019-10-04 16:39:03,018 [salt.fileclient  :1149][DEBUG   ][11769] No dest file found
2019-10-04 16:39:03,073 [salt.fileclient  :1230][INFO    ][11769] Fetching file from saltenv 'base', ** done ** 'php/macro.jinja'
2019-10-04 16:39:03,085 [salt.template    :26  ][PROFILE ][11769] Time (in seconds) to render '/var/cache/salt/minion/files/base/php/init.sls' using 'jinja' renderer: 1.06152105331
2019-10-04 16:39:03,085 [salt.template    :120 ][DEBUG   ][11769] Rendered data from file: /var/cache/salt/minion/files/base/php/init.sls:

# -*- coding: utf-8 -*-
# vim: ft=jinja











    
    



  

  
    
      
php_ppa_php:
  pkgrepo.managed:
    - ppa: ondrej/php
    - __env__:
      - LC_ALL: C.UTF-8
    - onlyif:
      - test ! -e /etc/apt/sources.list.d/ondrej-ubuntu-php-bionic.list 
      - test ! -e /etc/apt/sources.list.d/ondrej-php-bionic.list 
    - require_in:
      - pkg: php_install_php
  pkg.latest:
    - name: php
    - pkgs: ["php7.0"]
    - refresh: True
    - onchanges:
      - pkgrepo: php_ppa_php

    
  


php_install_php:
  pkg.installed:
    - name: php
    - pkgs: ["php7.0"]




2019-10-04 16:39:03,087 [salt.loaded.int.render.yaml:80  ][DEBUG   ][11769] Results of YAML rendering: 
OrderedDict([(u'php_ppa_php', OrderedDict([(u'pkgrepo.managed', [OrderedDict([(u'ppa', u'ondrej/php')]), OrderedDict([(u'__env__', [OrderedDict([(u'LC_ALL', u'C.UTF-8')])])]), OrderedDict([(u'onlyif', [u'test ! -e /etc/apt/sources.list.d/ondrej-ubuntu-php-bionic.list', u'test ! -e /etc/apt/sources.list.d/ondrej-php-bionic.list'])]), OrderedDict([(u'require_in', [OrderedDict([(u'pkg', u'php_install_php')])])])]), (u'pkg.latest', [OrderedDict([(u'name', u'php')]), OrderedDict([(u'pkgs', [u'php7.0'])]), OrderedDict([(u'refresh', True)]), OrderedDict([(u'onchanges', [OrderedDict([(u'pkgrepo', u'php_ppa_php')])])])])])), (u'php_install_php', OrderedDict([(u'pkg.installed', [OrderedDict([(u'name', u'php')]), OrderedDict([(u'pkgs', [u'php7.0'])])])]))])
2019-10-04 16:39:03,089 [salt.template    :26  ][PROFILE ][11769] Time (in seconds) to render '/var/cache/salt/minion/files/base/php/init.sls' using 'yaml' renderer: 0.00383114814758
2019-10-04 16:39:03,091 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded config.option
2019-10-04 16:39:03,103 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded pkg.mod_repo
2019-10-04 16:39:03,103 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded pkgrepo.managed
2019-10-04 16:39:03,104 [salt.state       :1819][INFO    ][11769] Running state [php_ppa_php] at time 16:39:03.104079
2019-10-04 16:39:03,104 [salt.state       :1852][INFO    ][11769] Executing state pkgrepo.managed for [php_ppa_php]
2019-10-04 16:39:03,251 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: ifttt.secret_key, ret: _|-
2019-10-04 16:39:03,252 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: ifttt:secret_key, ret: _|-
2019-10-04 16:39:03,425 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: pushbullet.api_key, ret: _|-
2019-10-04 16:39:03,426 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: pushbullet:api_key, ret: _|-
2019-10-04 16:39:03,451 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded systemd.booted
2019-10-04 16:39:03,528 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: victorops.api_key, ret: _|-
2019-10-04 16:39:03,529 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: victorops:api_key, ret: _|-
2019-10-04 16:39:03,763 [salt.loaded.int.module.win_dsc:43  ][DEBUG   ][11769] DSC: Only available on Windows systems
2019-10-04 16:39:03,775 [salt.loaded.int.module.win_psget:36  ][DEBUG   ][11769] Module PSGet: Only available on Windows systems
2019-10-04 16:39:03,783 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded platform.is_windows
2019-10-04 16:39:03,808 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad acme.cert: 'acme' __virtual__ returned False: The ACME execution module cannot be loaded: letsencrypt-auto not installed.
2019-10-04 16:39:03,817 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded apache.config
2019-10-04 16:39:03,817 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded apache.a2enconf
2019-10-04 16:39:03,818 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded apache.a2enmod
2019-10-04 16:39:03,818 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded apache.a2ensite
2019-10-04 16:39:03,830 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad augeas.execute: 'augeas.execute' is not available.
2019-10-04 16:39:03,831 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded azurearm_compute.availability_set_create_or_update
2019-10-04 16:39:03,832 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded azurearm_network.check_ip_address_availability
2019-10-04 16:39:03,832 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded azurearm_resource.resource_group_check_existence
2019-10-04 16:39:03,834 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto3_elasticache.cache_cluster_exists
2019-10-04 16:39:03,835 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto3_route53.find_hosted_zone
2019-10-04 16:39:03,835 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto3_sns.topic_exists
2019-10-04 16:39:03,837 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_apigateway.describe_apis
2019-10-04 16:39:03,838 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_asg.exists
2019-10-04 16:39:03,838 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_cfn.exists
2019-10-04 16:39:03,839 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_cloudfront.get_distribution
2019-10-04 16:39:03,839 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_cloudtrail.exists
2019-10-04 16:39:03,840 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_cloudwatch.get_alarm
2019-10-04 16:39:03,840 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_cloudwatch_event.exists
2019-10-04 16:39:03,841 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_cognitoidentity.describe_identity_pools
2019-10-04 16:39:03,841 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_datapipeline.create_pipeline
2019-10-04 16:39:03,842 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_dynamodb.exists
2019-10-04 16:39:03,843 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_ec2.get_key
2019-10-04 16:39:03,844 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_elasticache.exists
2019-10-04 16:39:03,844 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_elasticsearch_domain.exists
2019-10-04 16:39:03,845 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_elb.exists
2019-10-04 16:39:03,846 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_elbv2.target_group_exists
2019-10-04 16:39:03,846 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_iam.get_user
2019-10-04 16:39:03,847 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_iam.role_exists
2019-10-04 16:39:03,848 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_iot.policy_exists
2019-10-04 16:39:03,848 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_kinesis.exists
2019-10-04 16:39:03,849 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_kms.describe_key
2019-10-04 16:39:03,850 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_lambda.function_exists
2019-10-04 16:39:03,850 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_asg.exists
2019-10-04 16:39:03,851 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_rds.exists
2019-10-04 16:39:03,851 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_route53.get_record
2019-10-04 16:39:03,852 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_s3.get_object_metadata
2019-10-04 16:39:03,853 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_s3_bucket.exists
2019-10-04 16:39:03,853 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_secgroup.exists
2019-10-04 16:39:03,854 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_sns.exists
2019-10-04 16:39:03,854 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_sqs.exists
2019-10-04 16:39:03,856 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded boto_vpc.exists
2019-10-04 16:39:03,856 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded bower.list
2019-10-04 16:39:03,858 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded chef.client
2019-10-04 16:39:03,858 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded chocolatey.install
2019-10-04 16:39:03,859 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded cimc.get_system_info
2019-10-04 16:39:03,859 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded cisconso.set_data_value
2019-10-04 16:39:03,862 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded cyg.list
2019-10-04 16:39:03,863 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded ddns.update
2019-10-04 16:39:03,864 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded chassis.cmd
2019-10-04 16:39:03,876 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad docker.version: 'docker.version' is not available.
2019-10-04 16:39:03,885 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad docker.version: 'docker.version' is not available.
2019-10-04 16:39:03,894 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad docker.version: 'docker.version' is not available.
2019-10-04 16:39:03,904 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad docker.version: 'docker.version' is not available.
2019-10-04 16:39:03,906 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded eselect.exec_action
2019-10-04 16:39:03,920 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded esxi.cmd
2019-10-04 16:39:03,926 [salt.loaded.int.module.cmdmod:397 ][INFO    ][11769] Executing command [u'git', u'--version'] in directory '/root'
2019-10-04 16:39:04,200 [salt.loaded.int.module.cmdmod:843 ][DEBUG   ][11769] stdout: git version 2.17.1
2019-10-04 16:39:04,202 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded github.list_users
2019-10-04 16:39:04,203 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded glanceng.image_get
2019-10-04 16:39:04,205 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded glusterfs.list_volumes
2019-10-04 16:39:04,206 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded elasticsearch.exists
2019-10-04 16:39:04,208 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: grafana_version, ret: _|-
2019-10-04 16:39:04,208 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: grafana_version, ret: _|-
2019-10-04 16:39:04,212 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded icinga2.generate_ticket
2019-10-04 16:39:04,212 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded ifttt.trigger_event
2019-10-04 16:39:04,223 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad influxdb08.db_exists: 'influxdb08.db_exists' is not available.
2019-10-04 16:39:04,232 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad influxdb08.db_exists: 'influxdb08.db_exists' is not available.
2019-10-04 16:39:04,241 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad influxdb.db_exists: 'influxdb.db_exists' is not available.
2019-10-04 16:39:04,250 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad influxdb.db_exists: 'influxdb.db_exists' is not available.
2019-10-04 16:39:04,260 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad influxdb.db_exists: 'influxdb.db_exists' is not available.
2019-10-04 16:39:04,269 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad influxdb.db_exists: 'influxdb.db_exists' is not available.
2019-10-04 16:39:04,273 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded ipset.version
2019-10-04 16:39:04,274 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded kapacitor.version
2019-10-04 16:39:04,276 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded keystone.auth
2019-10-04 16:39:04,276 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded keystoneng.domain_get
2019-10-04 16:39:04,276 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded keystoneng.endpoint_get
2019-10-04 16:39:04,277 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded keystoneng.group_get
2019-10-04 16:39:04,277 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded keystoneng.project_get
2019-10-04 16:39:04,278 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded keystoneng.role_get
2019-10-04 16:39:04,279 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded keystoneng.role_grant
2019-10-04 16:39:04,279 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded keystoneng.service_get
2019-10-04 16:39:04,280 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded keystoneng.user_get
2019-10-04 16:39:04,290 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad kubernetes.ping: 'kubernetes.ping' is not available.
2019-10-04 16:39:04,290 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded layman.add
2019-10-04 16:39:04,294 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded logadm.list_conf
2019-10-04 16:39:04,295 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded lvs.get_rules
2019-10-04 16:39:04,295 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded lvs.get_rules
2019-10-04 16:39:04,296 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded lxd.version
2019-10-04 16:39:04,297 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded lxd.version
2019-10-04 16:39:04,297 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded lxd.version
2019-10-04 16:39:04,298 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded lxd.version
2019-10-04 16:39:04,299 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded makeconf.get_var
2019-10-04 16:39:04,301 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded memcached.status
2019-10-04 16:39:04,303 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded mongodb.db_exists
2019-10-04 16:39:04,303 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded mongodb.user_exists
2019-10-04 16:39:04,304 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded monit.summary
2019-10-04 16:39:04,305 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded mssql.version
2019-10-04 16:39:04,305 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded mssql.version
2019-10-04 16:39:04,305 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded mssql.version
2019-10-04 16:39:04,306 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded mssql.version
2019-10-04 16:39:04,307 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded mysql.db_exists
2019-10-04 16:39:04,307 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded mysql.grant_exists
2019-10-04 16:39:04,307 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded mysql.query
2019-10-04 16:39:04,308 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded mysql.user_create
2019-10-04 16:39:04,312 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded neutronng.list_networks
2019-10-04 16:39:04,312 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded neutronng.list_subnets
2019-10-04 16:39:04,313 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded neutronng.list_subnets
2019-10-04 16:39:04,314 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded neutronng.list_subnets
2019-10-04 16:39:04,315 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded nftables.version
2019-10-04 16:39:04,316 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded npm.list
2019-10-04 16:39:04,316 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded nxos.cmd
2019-10-04 16:39:04,317 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded openvswitch.bridge_create
2019-10-04 16:39:04,318 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded openvswitch.port_add
2019-10-04 16:39:04,319 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded panos.commit
2019-10-04 16:39:04,321 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded pdbedit.create
2019-10-04 16:39:04,322 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded pecl.list
2019-10-04 16:39:04,501 [pip.utils        :70  ][DEBUG   ][11769] lzma module is not available
2019-10-04 16:39:04,503 [pip.vcs          :60  ][DEBUG   ][11769] Registered VCS backend: git
2019-10-04 16:39:04,518 [pip.vcs          :60  ][DEBUG   ][11769] Registered VCS backend: hg
2019-10-04 16:39:04,568 [pip.vcs          :60  ][DEBUG   ][11769] Registered VCS backend: svn
2019-10-04 16:39:04,569 [pip.vcs          :60  ][DEBUG   ][11769] Registered VCS backend: bzr
2019-10-04 16:39:04,636 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded portage_config.get_missing_flags
2019-10-04 16:39:04,637 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded postgres.cluster_exists
2019-10-04 16:39:04,638 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded postgres.user_exists
2019-10-04 16:39:04,639 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded postgres.create_extension
2019-10-04 16:39:04,640 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded postgres.group_create
2019-10-04 16:39:04,640 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded postgres.datadir_init
2019-10-04 16:39:04,641 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded postgres.language_create
2019-10-04 16:39:04,642 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded postgres.privileges_grant
2019-10-04 16:39:04,642 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded postgres.schema_exists
2019-10-04 16:39:04,643 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded postgres.tablespace_exists
2019-10-04 16:39:04,643 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded postgres.user_exists
2019-10-04 16:39:04,646 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded quota.report
2019-10-04 16:39:04,659 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad rbac.profile_list: 'rbac.profile_list' is not available.
2019-10-04 16:39:04,660 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded rdp.enable
2019-10-04 16:39:04,669 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad redis.set_key: 'redis.set_key' is not available.
2019-10-04 16:39:04,673 [salt.config      :2185][DEBUG   ][11769] Reading configuration from /etc/salt/minion
2019-10-04 16:39:04,674 [salt.config      :2329][DEBUG   ][11769] Including configuration from '/etc/salt/minion.d/_schedule.conf'
2019-10-04 16:39:04,674 [salt.config      :2185][DEBUG   ][11769] Reading configuration from /etc/salt/minion.d/_schedule.conf
2019-10-04 16:39:04,675 [salt.config      :3666][DEBUG   ][11769] Using cached minion ID from /etc/salt/minion_id: ussc-tst-worker-vm1
2019-10-04 16:39:04,898 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad reg.read_value: 'reg.read_value' is not available.
2019-10-04 16:39:04,901 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded selinux.getenforce
2019-10-04 16:39:04,912 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad vmadm.create: 'vmadm.create' is not available.
2019-10-04 16:39:04,913 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded snapper.diff
2019-10-04 16:39:04,913 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded splunk.list_users
2019-10-04 16:39:04,914 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded splunk_search.get
2019-10-04 16:39:04,919 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded tomcat.status
2019-10-04 16:39:04,920 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded trafficserver.set_config
2019-10-04 16:39:04,921 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded vagrant.version
2019-10-04 16:39:04,922 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded victorops.create_event
2019-10-04 16:39:04,923 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded virt.node_info
2019-10-04 16:39:04,924 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded win_dacl.add_ace
2019-10-04 16:39:04,925 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded win_dns_client.add_dns
2019-10-04 16:39:04,935 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad firewall.get_config: 'firewall.get_config' is not available.
2019-10-04 16:39:04,936 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded win_iis.create_site
2019-10-04 16:39:04,945 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad lgpo.set: 'lgpo.set' is not available.
2019-10-04 16:39:04,946 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded win_path.rehash
2019-10-04 16:39:04,947 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded win_pki.get_stores
2019-10-04 16:39:04,947 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded win_servermanager.install
2019-10-04 16:39:04,948 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded win_smtp_server.get_server_setting
2019-10-04 16:39:04,948 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded win_snmp.get_agent_settings
2019-10-04 16:39:04,950 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded wordpress.show_plugin
2019-10-04 16:39:04,951 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded x509.get_pem_entry
2019-10-04 16:39:04,952 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded xmpp.send_msg
2019-10-04 16:39:04,957 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded zk_concurrency.lock
2019-10-04 16:39:04,958 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded zonecfg.create
2019-10-04 16:39:04,959 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded zookeeper.create
2019-10-04 16:39:04,966 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad pkgrepo.mod_run_check: 'pkgrepo.mod_run_check' is not available.
2019-10-04 16:39:04,966 [salt.loaded.int.module.cmdmod:397 ][INFO    ][11769] Executing command 'test ! -e /etc/apt/sources.list.d/ondrej-ubuntu-php-bionic.list' in directory '/root'
2019-10-04 16:39:04,978 [salt.state       :889 ][DEBUG   ][11769] Last command return code: 0
2019-10-04 16:39:04,980 [salt.loaded.int.module.cmdmod:397 ][INFO    ][11769] Executing command 'test ! -e /etc/apt/sources.list.d/ondrej-php-bionic.list' in directory '/root'
2019-10-04 16:39:04,990 [salt.state       :889 ][DEBUG   ][11769] Last command return code: 0
2019-10-04 16:39:05,035 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command saltutil.find_job with jid 20191004163905015180
2019-10-04 16:39:05,036 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'list', u'jid': u'20191004163905015180', u'tgt': [u'ussc-tst-worker-vm1'], u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'20191004163859974556'], u'fun': u'saltutil.find_job'}
2019-10-04 16:39:05,041 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:12-Job-20191004163905015180 added
2019-10-04 16:39:05,046 [salt.pillar      :57  ][DEBUG   ][11793] Determining pillar cache
2019-10-04 16:39:05,047 [salt.transport.zeromq:138 ][DEBUG   ][11793] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:05,048 [salt.crypt       :464 ][DEBUG   ][11793] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:05,050 [salt.transport.zeromq:209 ][DEBUG   ][11793] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:05,050 [salt.transport.zeromq:1189][DEBUG   ][11793] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:05,180 [salt.loaded.int.module.cmdmod:397 ][INFO    ][11769] Executing command [u'apt-add-repository', u'-y', u'ppa:ondrej/php'] in directory '/root'
2019-10-04 16:39:05,351 [salt.crypt       :200 ][DEBUG   ][11793] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:39:05,352 [salt.crypt       :802 ][DEBUG   ][11793] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:39:05,358 [salt.transport.zeromq:233 ][DEBUG   ][11793] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:05,435 [salt.utils.lazy  :104 ][DEBUG   ][11793] LazyLoaded jinja.render
2019-10-04 16:39:05,437 [salt.utils.lazy  :104 ][DEBUG   ][11793] LazyLoaded yaml.render
2019-10-04 16:39:05,440 [salt.minion      :1608][INFO    ][11793] Starting a new job 20191004163905015180 with PID 11793
2019-10-04 16:39:05,443 [salt.utils.lazy  :107 ][DEBUG   ][11793] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:39:05,445 [salt.utils.lazy  :104 ][DEBUG   ][11793] LazyLoaded saltutil.find_job
2019-10-04 16:39:05,447 [salt.minion      :806 ][DEBUG   ][11793] Minion return retry timer set to 9 seconds (randomized)
2019-10-04 16:39:05,448 [salt.minion      :1936][INFO    ][11793] Returning information for job: 20191004163905015180
2019-10-04 16:39:05,449 [salt.transport.zeromq:138 ][DEBUG   ][11793] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:05,449 [salt.crypt       :464 ][DEBUG   ][11793] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:05,451 [salt.transport.zeromq:209 ][DEBUG   ][11793] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:05,451 [salt.transport.zeromq:1189][DEBUG   ][11793] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:05,547 [salt.transport.zeromq:233 ][DEBUG   ][11793] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:05,548 [salt.minion      :1786][DEBUG   ][11793] minion return: {u'fun_args': [u'20191004163859974556'], u'jid': u'20191004163905015180', u'return': {'tgt_type': 'glob', 'jid': '20191004163859974556', 'tgt': '*work*', 'pid': 11769, 'ret': '', 'user': 'sudo_gjohnson', 'arg': ['php'], 'fun': 'state.apply'}, u'retcode': 0, u'success': True, u'fun': u'saltutil.find_job'}
2019-10-04 16:39:05,979 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:12-Job-20191004163905015180 cleaned up
2019-10-04 16:39:12,844 [salt.loaded.int.module.cmdmod:397 ][INFO    ][11769] Executing command [u'apt-get', u'-q', u'update'] in directory '/root'
2019-10-04 16:39:14,640 [salt.state       :320 ][INFO    ][11769] {u'repo': u'ppa:ondrej/php'}
2019-10-04 16:39:14,640 [salt.state       :1997][INFO    ][11769] Completed state [php_ppa_php] at time 16:39:14.640910 (duration_in_ms=11536.831)
2019-10-04 16:39:14,650 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad pkg.ex_mod_init: 'pkg.ex_mod_init' is not available.
2019-10-04 16:39:14,651 [salt.state       :1819][INFO    ][11769] Running state [php] at time 16:39:14.651266
2019-10-04 16:39:14,651 [salt.state       :1852][INFO    ][11769] Executing state pkg.latest for [php]
2019-10-04 16:39:14,661 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad pkg.normalize_name: 'pkg.normalize_name' is not available.
2019-10-04 16:39:14,670 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad pkg.resolve_capabilities: 'pkg.resolve_capabilities' is not available.
2019-10-04 16:39:14,671 [salt.loaded.int.module.cmdmod:397 ][INFO    ][11769] Executing command [u'dpkg-query', u'--showformat', u'${Status} ${Package} ${Version} ${Architecture}', u'-W'] in directory '/root'
2019-10-04 16:39:14,703 [salt.loaded.int.module.cmdmod:397 ][INFO    ][11769] Executing command [u'apt-get', u'-q', u'update'] in directory '/root'
2019-10-04 16:39:15,062 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command saltutil.find_job with jid 20191004163915042650
2019-10-04 16:39:15,063 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'list', u'jid': u'20191004163915042650', u'tgt': [u'ussc-tst-worker-vm1'], u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'20191004163859974556'], u'fun': u'saltutil.find_job'}
2019-10-04 16:39:15,070 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:13-Job-20191004163915042650 added
2019-10-04 16:39:15,077 [salt.pillar      :57  ][DEBUG   ][12825] Determining pillar cache
2019-10-04 16:39:15,079 [salt.transport.zeromq:138 ][DEBUG   ][12825] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:15,079 [salt.crypt       :464 ][DEBUG   ][12825] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:15,081 [salt.transport.zeromq:209 ][DEBUG   ][12825] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:15,082 [salt.transport.zeromq:1189][DEBUG   ][12825] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:15,366 [salt.crypt       :200 ][DEBUG   ][12825] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:39:15,367 [salt.crypt       :802 ][DEBUG   ][12825] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:39:15,371 [salt.transport.zeromq:233 ][DEBUG   ][12825] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:15,442 [salt.utils.lazy  :104 ][DEBUG   ][12825] LazyLoaded jinja.render
2019-10-04 16:39:15,443 [salt.utils.lazy  :104 ][DEBUG   ][12825] LazyLoaded yaml.render
2019-10-04 16:39:15,446 [salt.minion      :1608][INFO    ][12825] Starting a new job 20191004163915042650 with PID 12825
2019-10-04 16:39:15,449 [salt.utils.lazy  :107 ][DEBUG   ][12825] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:39:15,452 [salt.utils.lazy  :104 ][DEBUG   ][12825] LazyLoaded saltutil.find_job
2019-10-04 16:39:15,454 [salt.minion      :806 ][DEBUG   ][12825] Minion return retry timer set to 6 seconds (randomized)
2019-10-04 16:39:15,455 [salt.minion      :1936][INFO    ][12825] Returning information for job: 20191004163915042650
2019-10-04 16:39:15,456 [salt.transport.zeromq:138 ][DEBUG   ][12825] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:15,456 [salt.crypt       :464 ][DEBUG   ][12825] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:15,458 [salt.transport.zeromq:209 ][DEBUG   ][12825] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:15,458 [salt.transport.zeromq:1189][DEBUG   ][12825] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:15,559 [salt.transport.zeromq:233 ][DEBUG   ][12825] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:15,561 [salt.minion      :1786][DEBUG   ][12825] minion return: {u'fun_args': [u'20191004163859974556'], u'jid': u'20191004163915042650', u'return': {'tgt_type': 'glob', 'jid': '20191004163859974556', 'tgt': '*work*', 'pid': 11769, 'ret': '', 'user': 'sudo_gjohnson', 'arg': ['php'], 'fun': 'state.apply'}, u'retcode': 0, u'success': True, u'fun': u'saltutil.find_job'}
2019-10-04 16:39:15,980 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:13-Job-20191004163915042650 cleaned up
2019-10-04 16:39:16,564 [salt.loaded.int.module.cmdmod:397 ][INFO    ][11769] Executing command [u'apt-cache', u'-q', u'policy', u'php7.0'] in directory '/root'
2019-10-04 16:39:16,666 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad pkg.normalize_name: 'pkg.normalize_name' is not available.
2019-10-04 16:39:16,667 [salt.loaded.int.module.cmdmod:397 ][INFO    ][11769] Executing command [u'dpkg', u'--get-selections', u'*'] in directory '/root'
2019-10-04 16:39:16,701 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: systemd.scope, ret: _|-
2019-10-04 16:39:16,701 [salt.loaded.int.module.cmdmod:397 ][INFO    ][11769] Executing command [u'systemd-run', u'--scope', u'apt-get', u'-q', u'-y', u'-o', u'DPkg::Options::=--force-confold', u'-o', u'DPkg::Options::=--force-confdef', u'install', u'php7.0'] in directory '/root'
2019-10-04 16:39:25,283 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command saltutil.find_job with jid 20191004163925263092
2019-10-04 16:39:25,284 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'list', u'jid': u'20191004163925263092', u'tgt': [u'ussc-tst-worker-vm1'], u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'20191004163859974556'], u'fun': u'saltutil.find_job'}
2019-10-04 16:39:25,290 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:14-Job-20191004163925263092 added
2019-10-04 16:39:25,297 [salt.pillar      :57  ][DEBUG   ][13244] Determining pillar cache
2019-10-04 16:39:25,298 [salt.transport.zeromq:138 ][DEBUG   ][13244] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:25,299 [salt.crypt       :464 ][DEBUG   ][13244] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:25,300 [salt.transport.zeromq:209 ][DEBUG   ][13244] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:25,301 [salt.transport.zeromq:1189][DEBUG   ][13244] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:25,598 [salt.crypt       :200 ][DEBUG   ][13244] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:39:25,598 [salt.crypt       :802 ][DEBUG   ][13244] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:39:25,603 [salt.transport.zeromq:233 ][DEBUG   ][13244] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:25,648 [salt.utils.lazy  :104 ][DEBUG   ][13244] LazyLoaded jinja.render
2019-10-04 16:39:25,650 [salt.utils.lazy  :104 ][DEBUG   ][13244] LazyLoaded yaml.render
2019-10-04 16:39:25,652 [salt.minion      :1608][INFO    ][13244] Starting a new job 20191004163925263092 with PID 13244
2019-10-04 16:39:25,653 [salt.utils.lazy  :107 ][DEBUG   ][13244] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:39:25,656 [salt.utils.lazy  :104 ][DEBUG   ][13244] LazyLoaded saltutil.find_job
2019-10-04 16:39:25,657 [salt.minion      :806 ][DEBUG   ][13244] Minion return retry timer set to 9 seconds (randomized)
2019-10-04 16:39:25,658 [salt.minion      :1936][INFO    ][13244] Returning information for job: 20191004163925263092
2019-10-04 16:39:25,658 [salt.transport.zeromq:138 ][DEBUG   ][13244] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:25,658 [salt.crypt       :464 ][DEBUG   ][13244] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:25,659 [salt.transport.zeromq:209 ][DEBUG   ][13244] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:25,660 [salt.transport.zeromq:1189][DEBUG   ][13244] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:25,756 [salt.transport.zeromq:233 ][DEBUG   ][13244] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:25,757 [salt.minion      :1786][DEBUG   ][13244] minion return: {u'fun_args': [u'20191004163859974556'], u'jid': u'20191004163925263092', u'return': {'tgt_type': 'glob', 'jid': '20191004163859974556', 'tgt': '*work*', 'pid': 11769, 'ret': '', 'user': 'sudo_gjohnson', 'arg': ['php'], 'fun': 'state.apply'}, u'retcode': 0, u'success': True, u'fun': u'saltutil.find_job'}
2019-10-04 16:39:25,979 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:14-Job-20191004163925263092 cleaned up
2019-10-04 16:39:35,484 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command saltutil.find_job with jid 20191004163935463929
2019-10-04 16:39:35,484 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'list', u'jid': u'20191004163935463929', u'tgt': [u'ussc-tst-worker-vm1'], u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'20191004163859974556'], u'fun': u'saltutil.find_job'}
2019-10-04 16:39:35,491 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:15-Job-20191004163935463929 added
2019-10-04 16:39:35,494 [salt.pillar      :57  ][DEBUG   ][16344] Determining pillar cache
2019-10-04 16:39:35,496 [salt.transport.zeromq:138 ][DEBUG   ][16344] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:35,496 [salt.crypt       :464 ][DEBUG   ][16344] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:35,498 [salt.transport.zeromq:209 ][DEBUG   ][16344] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:35,501 [salt.transport.zeromq:1189][DEBUG   ][16344] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:35,794 [salt.crypt       :200 ][DEBUG   ][16344] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:39:35,794 [salt.crypt       :802 ][DEBUG   ][16344] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:39:35,798 [salt.transport.zeromq:233 ][DEBUG   ][16344] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:35,870 [salt.utils.lazy  :104 ][DEBUG   ][16344] LazyLoaded jinja.render
2019-10-04 16:39:35,872 [salt.utils.lazy  :104 ][DEBUG   ][16344] LazyLoaded yaml.render
2019-10-04 16:39:35,875 [salt.minion      :1608][INFO    ][16344] Starting a new job 20191004163935463929 with PID 16344
2019-10-04 16:39:35,877 [salt.utils.lazy  :107 ][DEBUG   ][16344] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:39:35,880 [salt.utils.lazy  :104 ][DEBUG   ][16344] LazyLoaded saltutil.find_job
2019-10-04 16:39:35,882 [salt.minion      :806 ][DEBUG   ][16344] Minion return retry timer set to 6 seconds (randomized)
2019-10-04 16:39:35,882 [salt.minion      :1936][INFO    ][16344] Returning information for job: 20191004163935463929
2019-10-04 16:39:35,883 [salt.transport.zeromq:138 ][DEBUG   ][16344] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:35,884 [salt.crypt       :464 ][DEBUG   ][16344] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:35,885 [salt.transport.zeromq:209 ][DEBUG   ][16344] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:35,886 [salt.transport.zeromq:1189][DEBUG   ][16344] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:35,983 [salt.transport.zeromq:233 ][DEBUG   ][16344] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:35,985 [salt.minion      :1786][DEBUG   ][16344] minion return: {u'fun_args': [u'20191004163859974556'], u'jid': u'20191004163935463929', u'return': {'tgt_type': 'glob', 'jid': '20191004163859974556', 'tgt': '*work*', 'pid': 11769, 'ret': '', 'user': 'sudo_gjohnson', 'arg': ['php'], 'fun': 'state.apply'}, u'retcode': 0, u'success': True, u'fun': u'saltutil.find_job'}
2019-10-04 16:39:36,979 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:15-Job-20191004163935463929 cleaned up
2019-10-04 16:39:45,500 [salt.minion      :1481][INFO    ][5852] User sudo_gjohnson Executing command saltutil.find_job with jid 20191004163945479986
2019-10-04 16:39:45,500 [salt.minion      :1488][DEBUG   ][5852] Command details {u'tgt_type': u'list', u'jid': u'20191004163945479986', u'tgt': [u'ussc-tst-worker-vm1'], u'ret': u'', u'user': u'sudo_gjohnson', u'arg': [u'20191004163859974556'], u'fun': u'saltutil.find_job'}
2019-10-04 16:39:45,508 [salt.utils.process:860 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:16-Job-20191004163945479986 added
2019-10-04 16:39:45,512 [salt.pillar      :57  ][DEBUG   ][19691] Determining pillar cache
2019-10-04 16:39:45,513 [salt.transport.zeromq:138 ][DEBUG   ][19691] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:45,514 [salt.crypt       :464 ][DEBUG   ][19691] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:45,515 [salt.transport.zeromq:209 ][DEBUG   ][19691] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:45,516 [salt.transport.zeromq:1189][DEBUG   ][19691] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:45,804 [salt.crypt       :200 ][DEBUG   ][19691] salt.crypt.get_rsa_key: Loading private key
2019-10-04 16:39:45,805 [salt.crypt       :802 ][DEBUG   ][19691] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-04 16:39:45,811 [salt.transport.zeromq:233 ][DEBUG   ][19691] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:45,913 [salt.utils.lazy  :104 ][DEBUG   ][19691] LazyLoaded jinja.render
2019-10-04 16:39:45,915 [salt.utils.lazy  :104 ][DEBUG   ][19691] LazyLoaded yaml.render
2019-10-04 16:39:45,918 [salt.minion      :1608][INFO    ][19691] Starting a new job 20191004163945479986 with PID 19691
2019-10-04 16:39:45,920 [salt.utils.lazy  :107 ][DEBUG   ][19691] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-04 16:39:45,924 [salt.utils.lazy  :104 ][DEBUG   ][19691] LazyLoaded saltutil.find_job
2019-10-04 16:39:45,927 [salt.minion      :806 ][DEBUG   ][19691] Minion return retry timer set to 10 seconds (randomized)
2019-10-04 16:39:45,927 [salt.minion      :1936][INFO    ][19691] Returning information for job: 20191004163945479986
2019-10-04 16:39:45,928 [salt.transport.zeromq:138 ][DEBUG   ][19691] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:45,929 [salt.crypt       :464 ][DEBUG   ][19691] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:45,930 [salt.transport.zeromq:209 ][DEBUG   ][19691] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:45,930 [salt.transport.zeromq:1189][DEBUG   ][19691] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:46,028 [salt.transport.zeromq:233 ][DEBUG   ][19691] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:46,029 [salt.minion      :1786][DEBUG   ][19691] minion return: {u'fun_args': [u'20191004163859974556'], u'jid': u'20191004163945479986', u'return': {'tgt_type': 'glob', 'jid': '20191004163859974556', 'tgt': '*work*', 'pid': 11769, 'ret': '', 'user': 'sudo_gjohnson', 'arg': ['php'], 'fun': 'state.apply'}, u'retcode': 0, u'success': True, u'fun': u'saltutil.find_job'}
2019-10-04 16:39:46,979 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:16-Job-20191004163945479986 cleaned up
2019-10-04 16:39:49,332 [salt.loaded.int.module.cmdmod:397 ][INFO    ][11769] Executing command [u'dpkg-query', u'--showformat', u'${Status} ${Package} ${Version} ${Architecture}', u'-W'] in directory '/root'
2019-10-04 16:39:49,375 [salt.state       :320 ][INFO    ][11769] Made the following changes:
'libaprutil1-ldap' changed from 'absent' to '1.6.1-2'
'libapr1' changed from 'absent' to '1.6.3-2'
'php7.0-common' changed from 'absent' to '7.0.33-11+ubuntu18.04.1+deb.sury.org+1'
'apache2-utils' changed from 'absent' to '2.4.29-1ubuntu4.11'
'apache2-data' changed from 'absent' to '2.4.29-1ubuntu4.11'
'php7.0-readline' changed from 'absent' to '7.0.33-11+ubuntu18.04.1+deb.sury.org+1'
'libpcre3' changed from '2:8.39-9' to '2:8.43-1+ubuntu18.04.1+deb.sury.org+1'
'libaprutil1' changed from 'absent' to '1.6.1-2'
'php7.0-cli' changed from 'absent' to '7.0.33-11+ubuntu18.04.1+deb.sury.org+1'
'php7.0' changed from 'absent' to '7.0.33-11+ubuntu18.04.1+deb.sury.org+1'
'libaprutil1-dbd-sqlite3' changed from 'absent' to '1.6.1-2'
'libapache2-mod-php7.0' changed from 'absent' to '7.0.33-11+ubuntu18.04.1+deb.sury.org+1'
'php7.0-opcache' changed from 'absent' to '7.0.33-11+ubuntu18.04.1+deb.sury.org+1'
'php-common' changed from 'absent' to '2:69+ubuntu18.04.1+deb.sury.org+2+php7.3'
'apache2' changed from 'absent' to '2.4.29-1ubuntu4.11'
'liblua5.2-0' changed from 'absent' to '5.2.4-1.1build1'
'php7.0-json' changed from 'absent' to '7.0.33-11+ubuntu18.04.1+deb.sury.org+1'
'ssl-cert' changed from 'absent' to '1.0.39'
'apache2-bin' changed from 'absent' to '2.4.29-1ubuntu4.11'

2019-10-04 16:39:49,376 [salt.state       :1000][DEBUG   ][11769] Refreshing modules...
2019-10-04 16:39:49,396 [salt.state       :966 ][INFO    ][11769] Loading fresh modules for state activity
2019-10-04 16:39:49,432 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded jinja.render
2019-10-04 16:39:49,433 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded yaml.render
2019-10-04 16:39:49,435 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded saltutil.refresh_modules
2019-10-04 16:39:49,435 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded event.fire
2019-10-04 16:39:49,436 [salt.utils.event :323 ][DEBUG   ][11769] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pub.ipc
2019-10-04 16:39:49,436 [salt.utils.event :324 ][DEBUG   ][11769] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_c5b2bc5cd3_pull.ipc
2019-10-04 16:39:49,438 [salt.utils.event :738 ][DEBUG   ][11769] Sending event: tag = module_refresh; data = {u'_stamp': '2019-10-04T16:39:49.437944'}
2019-10-04 16:39:49,438 [salt.transport.ipc:364 ][DEBUG   ][11769] Closing IPCMessageClient instance
2019-10-04 16:39:49,439 [salt.state       :1997][INFO    ][11769] Completed state [php] at time 16:39:49.439181 (duration_in_ms=34787.914)
2019-10-04 16:39:49,439 [salt.minion      :2357][DEBUG   ][5852] Minion of 'prd-ssm.reachcm.com' is handling event tag 'module_refresh'
2019-10-04 16:39:49,440 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded config.option
2019-10-04 16:39:49,440 [salt.minion      :2160][DEBUG   ][5852] Refreshing modules. Notify=False
2019-10-04 16:39:49,440 [salt.loader      :747 ][DEBUG   ][5852] Grains refresh requested. Refreshing grains.
2019-10-04 16:39:49,441 [salt.config      :2185][DEBUG   ][5852] Reading configuration from /etc/salt/minion
2019-10-04 16:39:49,442 [salt.config      :2329][DEBUG   ][5852] Including configuration from '/etc/salt/minion.d/_schedule.conf'
2019-10-04 16:39:49,443 [salt.config      :2185][DEBUG   ][5852] Reading configuration from /etc/salt/minion.d/_schedule.conf
2019-10-04 16:39:49,444 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded pkg.install
2019-10-04 16:39:49,445 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded pkg.installed
2019-10-04 16:39:49,445 [salt.state       :1819][INFO    ][11769] Running state [php] at time 16:39:49.445814
2019-10-04 16:39:49,446 [salt.state       :1852][INFO    ][11769] Executing state pkg.installed for [php]
2019-10-04 16:39:49,701 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: ifttt.secret_key, ret: _|-
2019-10-04 16:39:49,704 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: ifttt:secret_key, ret: _|-
2019-10-04 16:39:49,857 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: pushbullet.api_key, ret: _|-
2019-10-04 16:39:49,858 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: pushbullet:api_key, ret: _|-
2019-10-04 16:39:49,878 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded systemd.booted
2019-10-04 16:39:49,903 [salt.loader      :1631][DEBUG   ][11769] Error loading module.swarm: __init__ failed
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/salt/loader.py", line 1624, in _load_module
    module_init(self.opts)
  File "/usr/lib/python2.7/dist-packages/salt/modules/swarm.py", line 53, in __init__
    __context__['client'] = docker.from_env()
AttributeError: 'module' object has no attribute 'from_env'
2019-10-04 16:39:49,927 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: victorops.api_key, ret: _|-
2019-10-04 16:39:49,927 [salt.loaded.int.module.config:398 ][DEBUG   ][11769] key: victorops:api_key, ret: _|-
2019-10-04 16:39:49,979 [salt.utils.lazy  :104 ][DEBUG   ][5852] LazyLoaded config.merge
2019-10-04 16:39:49,981 [salt.utils.lazy  :104 ][DEBUG   ][5852] LazyLoaded mine.update
2019-10-04 16:39:50,155 [salt.loaded.int.module.win_dsc:43  ][DEBUG   ][11769] DSC: Only available on Windows systems
2019-10-04 16:39:50,162 [salt.loaded.int.module.win_psget:36  ][DEBUG   ][11769] Module PSGet: Only available on Windows systems
2019-10-04 16:39:50,167 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded platform.is_windows
2019-10-04 16:39:50,189 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad pkg.resolve_capabilities: 'pkg.resolve_capabilities' is not available.
2019-10-04 16:39:50,199 [salt.utils.lazy  :107 ][DEBUG   ][11769] Could not LazyLoad pkg.normalize_name: 'pkg.normalize_name' is not available.
2019-10-04 16:39:50,199 [salt.state       :320 ][INFO    ][11769] All specified packages are already installed
2019-10-04 16:39:50,200 [salt.state       :1997][INFO    ][11769] Completed state [php] at time 16:39:50.200093 (duration_in_ms=754.279)
2019-10-04 16:39:50,200 [salt.state       :2801][DEBUG   ][11769] File /var/cache/salt/minion/accumulator/139875879725328 does not exist, no need to cleanup
2019-10-04 16:39:50,201 [salt.utils.lazy  :104 ][DEBUG   ][11769] LazyLoaded state.check_result
2019-10-04 16:39:50,202 [salt.minion      :806 ][DEBUG   ][11769] Minion return retry timer set to 5 seconds (randomized)
2019-10-04 16:39:50,202 [salt.minion      :1936][INFO    ][11769] Returning information for job: 20191004163859974556
2019-10-04 16:39:50,203 [salt.transport.zeromq:138 ][DEBUG   ][11769] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506', u'aes')
2019-10-04 16:39:50,203 [salt.crypt       :464 ][DEBUG   ][11769] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ussc-tst-worker-vm1', u'tcp://40.122.203.8:34506')
2019-10-04 16:39:50,204 [salt.transport.zeromq:209 ][DEBUG   ][11769] Connecting the Minion to the Master URI (for the return server): tcp://40.122.203.8:34506
2019-10-04 16:39:50,205 [salt.transport.zeromq:1189][DEBUG   ][11769] Trying to connect to: tcp://40.122.203.8:34506
2019-10-04 16:39:50,299 [salt.transport.zeromq:233 ][DEBUG   ][11769] Closing AsyncZeroMQReqChannel instance
2019-10-04 16:39:50,300 [salt.minion      :1786][DEBUG   ][11769] minion return: {u'fun_args': [u'php'], u'jid': u'20191004163859974556', u'return': {u'pkg_|-php_install_php_|-php_|-installed': {u'comment': u'All specified packages are already installed', u'name': u'php7.0', u'start_time': '16:39:49.445814', u'result': True, u'duration': 754.279, u'__run_num__': 2, u'__sls__': u'php', u'changes': {}, u'__id__': u'php_install_php'}, u'pkgrepo_|-php_ppa_php_|-php_ppa_php_|-managed': {u'comment': u"Configured package repo 'php_ppa_php'", u'name': u'php_ppa_php', u'start_time': '16:39:03.104079', u'result': True, u'duration': 11536.831, u'__run_num__': 0, u'__sls__': u'php', u'changes': {u'repo': u'ppa:ondrej/php'}, u'__id__': u'php_ppa_php'}, u'pkg_|-php_ppa_php_|-php_|-latest': {u'comment': u'The following packages were successfully installed/upgraded: php7.0', u'name': u'php', u'start_time': '16:39:14.651267', u'result': True, u'duration': 34787.914, u'__run_num__': 1, u'__sls__': u'php', u'changes': {u'libaprutil1-ldap': {u'new': u'1.6.1-2', u'old': u''}, u'libapr1': {u'new': u'1.6.3-2', u'old': u''}, u'php7.0-common': {u'new': u'7.0.33-11+ubuntu18.04.1+deb.sury.org+1', u'old': u''}, u'apache2-utils': {u'new': u'2.4.29-1ubuntu4.11', u'old': u''}, u'apache2-data': {u'new': u'2.4.29-1ubuntu4.11', u'old': u''}, u'php7.0-readline': {u'new': u'7.0.33-11+ubuntu18.04.1+deb.sury.org+1', u'old': u''}, u'libpcre3': {u'new': u'2:8.43-1+ubuntu18.04.1+deb.sury.org+1', u'old': u'2:8.39-9'}, u'libaprutil1': {u'new': u'1.6.1-2', u'old': u''}, u'php7.0-cli': {u'new': u'7.0.33-11+ubuntu18.04.1+deb.sury.org+1', u'old': u''}, u'php7.0': {u'new': u'7.0.33-11+ubuntu18.04.1+deb.sury.org+1', u'old': u''}, u'libaprutil1-dbd-sqlite3': {u'new': u'1.6.1-2', u'old': u''}, u'libapache2-mod-php7.0': {u'new': u'7.0.33-11+ubuntu18.04.1+deb.sury.org+1', u'old': u''}, u'php7.0-opcache': {u'new': u'7.0.33-11+ubuntu18.04.1+deb.sury.org+1', u'old': u''}, u'php-common': {u'new': u'2:69+ubuntu18.04.1+deb.sury.org+2+php7.3', u'old': u''}, u'apache2': {u'new': u'2.4.29-1ubuntu4.11', u'old': u''}, u'liblua5.2-0': {u'new': u'5.2.4-1.1build1', u'old': u''}, u'php7.0-json': {u'new': u'7.0.33-11+ubuntu18.04.1+deb.sury.org+1', u'old': u''}, u'ssl-cert': {u'new': u'1.0.39', u'old': u''}, u'apache2-bin': {u'new': u'2.4.29-1ubuntu4.11', u'old': u''}}, u'__id__': u'php_ppa_php'}}, u'retcode': 0, u'success': True, u'fun': u'state.apply'}
2019-10-04 16:39:50,979 [salt.utils.process:869 ][DEBUG   ][5852] Subprocess SignalHandlingMultiprocessingProcess-1:11-Job-20191004163859974556 cleaned up
2019-10-04 16:42:14,422 [salt.utils.parsers:1071][WARNING ][5852] Minion received a SIGTERM. Exiting.
2019-10-04 16:42:14,422 [salt.cli.daemons :85  ][INFO    ][5852] Shutting down the Salt Minion
2019-10-04 16:42:14,423 [salt.log.setup   :1044][DEBUG   ][5852] Stopping the multiprocessing logging queue listener
2019-10-04 16:42:14,924 [salt.log.setup   :1050][DEBUG   ][5852] closing multiprocessing queue
2019-10-04 16:42:14,924 [salt.log.setup   :1052][DEBUG   ][5852] joining multiprocessing queue thread
2019-10-04 16:42:14,924 [salt.log.setup   :1066][DEBUG   ][5852] Stopped the multiprocessing logging queue listener

@myii
Copy link
Member

myii commented Oct 4, 2019 •
edited
Loading

From our Slack discussion:

include:
 - php
 - php.fpm.install
 - php.fpm.config
 - php.fpm.service
 - php.fpm.pools
 - php.pear
 - php.mongodb
 - php.mcrypt
 - php.bcmath
 - php.composer
 - php.dev
 - php.gd
 - php.gmp
 - php.json
 - php.ldap
 - php.mbstring
 - php.opcache
 - php.sqlite
 - php.sybase
 - php.xml
 - php.redis
  • php.cli isn't present.

@gj02ib65
Copy link
Author

gj02ib65 commented Oct 4, 2019

Thanks to @myii we figured out that this was a user (me) error....

Thank you!!

@gj02ib65 gj02ib65 closed this as completed Oct 4, 2019
@myii
Copy link
Member

myii commented Oct 4, 2019

You're welcome, @gj02ib65. Thanks for closing the issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@myii @gj02ib65