search

saltstack-formulas / php-formula

http://docs.saltstack.com/en/latest/topics/development/conventions/formulas.html
Other
57 stars 232 forks source link

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

Closed gj02ib65 closed 4 years ago

gj02ib65 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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
gj02ib65 commented 4 years ago

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

Thank you!!

myii commented 4 years ago

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