Salt: Dry-running state.highstate only returns the first change

[falzm]

Hello

When I run "state.highstate test=True" to dry-run changes, only the first change that would be made is displayed... is this a known behaviour or a bug?

For instance, when making several changes to states of a server and triggering a highstate command in dry-run mode (sorry for the long log traces):

root@tools-1:~# salt 'tools-1.*' state.highstate test=True
tools-1.*********.fr:
----------
          ID: packages.*********.fr.wheezy
    Function: pkgrepo.managed
        Name: deb http://packages.*********.fr/ wheezy main
      Result: True
     Comment: Package repo 'deb http://packages.*********.fr/ wheezy main' already configured
     Started: 21:46:20.479176
    Duration: 29.964 ms
     Changes:
----------
          ID: aptitude
    Function: pkg.installed
      Result: True
     Comment: Package aptitude is already installed.
     Started: 21:46:20.509282
    Duration: 206.965 ms
     Changes:
----------
          ID: /etc/apt/apt.conf.d/70debconf
    Function: file.managed
      Result: True
     Comment: The file /etc/apt/apt.conf.d/70debconf is in the correct state
     Started: 21:46:20.716388
    Duration: 2.223 ms
     Changes:
----------
          ID: bash-completion
    Function: pkg.installed
      Result: True
     Comment: Package bash-completion is already installed.
     Started: 21:46:20.718715
    Duration: 0.411 ms
     Changes:
----------
          ID: /etc/bash.bashrc
    Function: file.managed
      Result: True
     Comment: The file /etc/bash.bashrc is in the correct state
     Started: 21:46:20.719221
    Duration: 1.56 ms
     Changes:
----------
          ID: less
    Function: pkg.installed
      Result: True
     Comment: Package less is already installed.
     Started: 21:46:20.720880
    Duration: 0.381 ms
     Changes:
----------
          ID: /etc/profile.d/less.sh
    Function: file.managed
      Result: None
     Comment: The following values are set to be changed:
              newfile: /etc/profile.d/less.sh
     Started: 21:46:20.721546
    Duration: 1.434 ms
     Changes:

Summary
------------
Succeeded: 7 (unchanged=1)
Failed:    0
------------
Total states run:     7

Same locally using salt-call:

root@tools-1:~# salt-call state.highstate test=True
[INFO    ] Loading fresh modules for state activity
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://top.sls'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/modules'
[INFO    ] Syncing modules for environment 'base'
[INFO    ] Loading cache from salt://_modules, for base)
[INFO    ] Caching directory '_modules/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/states'
[INFO    ] Syncing states for environment 'base'
[INFO    ] Loading cache from salt://_states, for base)
[INFO    ] Caching directory '_states/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/grains'
[INFO    ] Syncing grains for environment 'base'
[INFO    ] Loading cache from salt://_grains, for base)
[INFO    ] Caching directory '_grains/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/renderers'
[INFO    ] Syncing renderers for environment 'base'
[INFO    ] Loading cache from salt://_renderers, for base)
[INFO    ] Caching directory '_renderers/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/returners'
[INFO    ] Syncing returners for environment 'base'
[INFO    ] Loading cache from salt://_returners, for base)
[INFO    ] Caching directory '_returners/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/outputters'
[INFO    ] Syncing outputters for environment 'base'
[INFO    ] Loading cache from salt://_outputters, for base)
[INFO    ] Caching directory '_outputters/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/utils'
[INFO    ] Syncing utils for environment 'base'
[INFO    ] Loading cache from salt://_utils, for base)
[INFO    ] Caching directory '_utils/' for environment 'base'
[INFO    ] Loading fresh modules for state activity
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://core.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://apt/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://bash/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://less/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://motd/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://openntpd/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://openssh/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://salt/minion.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://ssh_keys.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://sysctl.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://syslog-ng/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://tmux/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://vim/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://salt/master.sls'
[INFO    ] Running state [deb http://packages.*********.fr/ wheezy main] at time 21:49:54.858680
[INFO    ] Executing state pkgrepo.managed for deb http://packages.*********.fr/ wheezy main
[INFO    ] Package repo 'deb http://packages.*********.fr/ wheezy main' already configured
[INFO    ] Completed state [deb http://packages.*********.fr/ wheezy main] at time 21:49:54.899099
[INFO    ] Running state [aptitude] at time 21:49:54.899255
[INFO    ] Executing state pkg.installed for aptitude
[INFO    ] Executing command "dpkg-query --showformat='${Status} ${Package} ${Version} ${Architecture}\n' -W" in directory '/root'
[INFO    ] Package aptitude is already installed.
[INFO    ] Completed state [aptitude] at time 21:49:55.101126
[INFO    ] Running state [/etc/apt/apt.conf.d/70debconf] at time 21:49:55.101314
[INFO    ] Executing state file.managed for /etc/apt/apt.conf.d/70debconf
[INFO    ] The file /etc/apt/apt.conf.d/70debconf is in the correct state
[INFO    ] Completed state [/etc/apt/apt.conf.d/70debconf] at time 21:49:55.103659
[INFO    ] Running state [bash-completion] at time 21:49:55.103795
[INFO    ] Executing state pkg.installed for bash-completion
[INFO    ] Package bash-completion is already installed.
[INFO    ] Completed state [bash-completion] at time 21:49:55.104290
[INFO    ] Running state [/etc/bash.bashrc] at time 21:49:55.104415
[INFO    ] Executing state file.managed for /etc/bash.bashrc
[INFO    ] The file /etc/bash.bashrc is in the correct state
[INFO    ] Completed state [/etc/bash.bashrc] at time 21:49:55.106120
[INFO    ] Running state [less] at time 21:49:55.106256
[INFO    ] Executing state pkg.installed for less
[INFO    ] Package less is already installed.
[INFO    ] Completed state [less] at time 21:49:55.106735
[INFO    ] Running state [/etc/profile.d/less.sh] at time 21:49:55.107049
[INFO    ] Executing state file.managed for /etc/profile.d/less.sh
[INFO    ] {'newfile': '/etc/profile.d/less.sh'}
[INFO    ] The following values are set to be changed:
newfile: /etc/profile.d/less.sh

[INFO    ] Completed state [/etc/profile.d/less.sh] at time 21:49:55.108679
local:
----------
          ID: packages.*********.fr.wheezy
    Function: pkgrepo.managed
        Name: deb http://packages.*********.fr/ wheezy main
      Result: True
     Comment: Package repo 'deb http://packages.*********.fr/ wheezy main' already configured
     Started: 21:49:54.858680
    Duration: 40.419 ms
     Changes:
----------
          ID: aptitude
    Function: pkg.installed
      Result: True
     Comment: Package aptitude is already installed.
     Started: 21:49:54.899255
    Duration: 201.871 ms
     Changes:
----------
          ID: /etc/apt/apt.conf.d/70debconf
    Function: file.managed
      Result: True
     Comment: The file /etc/apt/apt.conf.d/70debconf is in the correct state
     Started: 21:49:55.101314
    Duration: 2.345 ms
     Changes:
----------
          ID: bash-completion
    Function: pkg.installed
      Result: True
     Comment: Package bash-completion is already installed.
     Started: 21:49:55.103795
    Duration: 0.495 ms
     Changes:
----------
          ID: /etc/bash.bashrc
    Function: file.managed
      Result: True
     Comment: The file /etc/bash.bashrc is in the correct state
     Started: 21:49:55.104415
    Duration: 1.705 ms
     Changes:
----------
          ID: less
    Function: pkg.installed
      Result: True
     Comment: Package less is already installed.
     Started: 21:49:55.106256
    Duration: 0.479 ms
     Changes:
----------
          ID: /etc/profile.d/less.sh
    Function: file.managed
      Result: None
     Comment: The following values are set to be changed:
              newfile: /etc/profile.d/less.sh
     Started: 21:49:55.107049
    Duration: 1.63 ms
     Changes:

Summary
------------
Succeeded: 7 (unchanged=1)
Failed:    0
------------
Total states run:     7
root@tools-1:~#

But when triggering the highstate for real, much more changes occur:

root@tools-1:~# salt-call state.highstate
[INFO    ] Loading fresh modules for state activity
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://top.sls'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/modules'
[INFO    ] Syncing modules for environment 'base'
[INFO    ] Loading cache from salt://_modules, for base)
[INFO    ] Caching directory '_modules/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/states'
[INFO    ] Syncing states for environment 'base'
[INFO    ] Loading cache from salt://_states, for base)
[INFO    ] Caching directory '_states/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/grains'
[INFO    ] Syncing grains for environment 'base'
[INFO    ] Loading cache from salt://_grains, for base)
[INFO    ] Caching directory '_grains/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/renderers'
[INFO    ] Syncing renderers for environment 'base'
[INFO    ] Loading cache from salt://_renderers, for base)
[INFO    ] Caching directory '_renderers/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/returners'
[INFO    ] Syncing returners for environment 'base'
[INFO    ] Loading cache from salt://_returners, for base)
[INFO    ] Caching directory '_returners/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/outputters'
[INFO    ] Syncing outputters for environment 'base'
[INFO    ] Loading cache from salt://_outputters, for base)
[INFO    ] Caching directory '_outputters/' for environment 'base'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/utils'
[INFO    ] Syncing utils for environment 'base'
[INFO    ] Loading cache from salt://_utils, for base)
[INFO    ] Caching directory '_utils/' for environment 'base'
[INFO    ] Loading fresh modules for state activity
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://core.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://apt/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://bash/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://less/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://motd/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://openntpd/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://openssh/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://salt/minion.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://ssh_keys.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://sysctl.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://syslog-ng/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://tmux/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://vim/init.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://salt/master.sls'
[INFO    ] Running state [deb http://packages.*********.fr/ wheezy main] at time 21:52:08.498498
[INFO    ] Executing state pkgrepo.managed for deb http://packages.*********.fr/ wheezy main
[INFO    ] Package repo 'deb http://packages.*********.fr/ wheezy main' already configured
[INFO    ] Completed state [deb http://packages.*********.fr/ wheezy main] at time 21:52:08.539240
[INFO    ] Running state [aptitude] at time 21:52:08.539399
[INFO    ] Executing state pkg.installed for aptitude
[INFO    ] Executing command "dpkg-query --showformat='${Status} ${Package} ${Version} ${Architecture}\n' -W" in directory '/root'
[INFO    ] Package aptitude is already installed.
[INFO    ] Completed state [aptitude] at time 21:52:08.743050
[INFO    ] Running state [/etc/apt/apt.conf.d/70debconf] at time 21:52:08.743248
[INFO    ] Executing state file.managed for /etc/apt/apt.conf.d/70debconf
[INFO    ] File /etc/apt/apt.conf.d/70debconf is in the correct state
[INFO    ] Completed state [/etc/apt/apt.conf.d/70debconf] at time 21:52:08.745457
[INFO    ] Running state [bash-completion] at time 21:52:08.745585
[INFO    ] Executing state pkg.installed for bash-completion
[INFO    ] Package bash-completion is already installed.
[INFO    ] Completed state [bash-completion] at time 21:52:08.746064
[INFO    ] Running state [/etc/bash.bashrc] at time 21:52:08.746188
[INFO    ] Executing state file.managed for /etc/bash.bashrc
[INFO    ] File /etc/bash.bashrc is in the correct state
[INFO    ] Completed state [/etc/bash.bashrc] at time 21:52:08.748258
[INFO    ] Running state [less] at time 21:52:08.748392
[INFO    ] Executing state pkg.installed for less
[INFO    ] Package less is already installed.
[INFO    ] Completed state [less] at time 21:52:08.748876
[INFO    ] Running state [/etc/profile.d/less.sh] at time 21:52:08.749193
[INFO    ] Executing state file.managed for /etc/profile.d/less.sh
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://less/files/etc/profile.d/less.sh'
[INFO    ] File changed:
New file
[INFO    ] Completed state [/etc/profile.d/less.sh] at time 21:52:09.074892
[INFO    ] Running state [/etc/motd] at time 21:52:09.075189
[INFO    ] Executing state file.managed for /etc/motd
[INFO    ] File /etc/motd is in the correct state
[INFO    ] Completed state [/etc/motd] at time 21:52:09.078376
[INFO    ] Running state [openntpd] at time 21:52:09.078657
[INFO    ] Executing state pkg.installed for openntpd
[INFO    ] Package openntpd is already installed.
[INFO    ] Completed state [openntpd] at time 21:52:09.079780
[INFO    ] Running state [/etc/openntpd/ntpd.conf] at time 21:52:09.080043
[INFO    ] Executing state file.managed for /etc/openntpd/ntpd.conf
[INFO    ] File /etc/openntpd/ntpd.conf is in the correct state
[INFO    ] Completed state [/etc/openntpd/ntpd.conf] at time 21:52:09.083006
[INFO    ] Running state [openssh-server] at time 21:52:09.083289
[INFO    ] Executing state pkg.installed for openssh-server
[INFO    ] Package openssh-server is already installed.
[INFO    ] Completed state [openssh-server] at time 21:52:09.084335
[INFO    ] Running state [/etc/ssh/sshd_config] at time 21:52:09.084595
[INFO    ] Executing state file.managed for /etc/ssh/sshd_config
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://openssh/templates/sshd_config.jinja'
[INFO    ] File /etc/ssh/sshd_config is in the correct state
[INFO    ] Completed state [/etc/ssh/sshd_config] at time 21:52:09.093154
[INFO    ] Running state [salt-minion] at time 21:52:09.093412
[INFO    ] Executing state pkg.installed for salt-minion
[INFO    ] Version 2014.7.0+ds-2~bpo70+1 of package 'salt-minion' is already installed.
[INFO    ] Completed state [salt-minion] at time 21:52:09.094354
[INFO    ] Running state [salt-minion] at time 21:52:09.094595
[INFO    ] Executing state service.running for salt-minion
[INFO    ] Executing command 'runlevel' in directory '/root'
[INFO    ] Executing command 'service salt-minion status' in directory '/root'
[INFO    ] The service salt-minion is already running
[INFO    ] Completed state [salt-minion] at time 21:52:09.118178
[INFO    ] Running state [/etc/salt/minion] at time 21:52:09.118479
[INFO    ] Executing state file.managed for /etc/salt/minion
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://salt/templates/minion.jinja'
[INFO    ] File changed:

---
+++
@@ -10,7 +10,7 @@
 # Per default the minion will automatically include all config files
 # from minion.d/*.conf (minion.d is a directory in the same directory
 # as the main minion config file).
-#default_include: minion.d/*.conf
+default_include: minion.d/*.conf

 # Set the location of the salt master server, if the master server cannot be
 # resolved, then the minion will fail to start.

[INFO    ] Completed state [/etc/salt/minion] at time 21:52:09.137354
[INFO    ] Running state [AAAAB3NzaC1yc2EAAAABIwAAAQEAvblupjNT3ctwB4Y3fylHRiNe1ObWipEfy/aYNx7lfFwJKM+3Ub0tqhUHxaG8sacgPKxB5bt2QVY7RavtGe+5UDg80QLCSfkbEgp8tr/x.....................] at time 21:52:09.137587
[INFO    ] Executing state ssh_auth.present for AAAAB3NzaC1yc2EAAAABIwAAAQEAvblupjNT3ctwB4Y3fylHRiNe1ObWipEfy/aYNx7lfFwJKM+3Ub0tqhUHxaG8sacgPKxB5bt2QVY7RavtGe+5UDg80QLCSfkbEgp8tr/x.....................
[INFO    ] The authorized host key AAAAB3NzaC1yc2EAAAABIwAAAQEAvblupjNT3ctwB4Y3fylHRiNe1ObWipEfy/aYNx7lfFwJKM+3Ub0tqhUHxaG8sacgPKxB5bt2QVY7RavtGe+5UDg80QLCSfkbEgp8tr/x..................... is already present for user root
[INFO    ] Completed state [AAAAB3NzaC1yc2EAAAABIwAAAQEAvblupjNT3ctwB4Y3fylHRiNe1ObWipEfy/aYNx7lfFwJKM+3Ub0tqhUHxaG8sacgPKxB5bt2QVY7RavtGe+5UDg80QLCSfkbEgp8tr/x.....................] at time 21:52:09.139750
[INFO    ] Running state [kernel.dmesg_restrict] at time 21:52:09.140012
[INFO    ] Executing state sysctl.present for kernel.dmesg_restrict
[INFO    ] Executing command 'sysctl -a' in directory '/root'
[INFO    ] Executing command 'sysctl -a' in directory '/root'
[INFO    ] Sysctl value kernel.dmesg_restrict = 1 is already set
[INFO    ] Completed state [kernel.dmesg_restrict] at time 21:52:09.222078
[INFO    ] Running state [AAAAB3NzaC1yc2EAAAADAQABAAABAQDFh6kfcJ7wf2AywaiiTVpn2yCBJUvK/XZkMln28x2x2dGp+WZ8GNOIUbeoUMHi0tzxpL9J+7wK4rtrxJ...........................] at time 21:52:09.222349
[INFO    ] Executing state ssh_auth.present for AAAAB3NzaC1yc2EAAAADAQABAAABAQDFh6kfcJ7wf2AywaiiTVpn2yCBJUvK/XZkMln28x2x2dGp+WZ8GNOIUbeoUMHi0tzxpL9J+7wK4rtrxJ...........................
[INFO    ] The authorized host key AAAAB3NzaC1yc2EAAAADAQABAAABAQDFh6kfcJ7wf2AywaiiTVpn2yCBJUvK/XZkMln28x2x2dGp+WZ8GNOIUbeoUMHi0tzxpL9J+7wK4rtrxJ........................... is already present for user root
[INFO    ] Completed state [AAAAB3NzaC1yc2EAAAADAQABAAABAQDFh6kfcJ7wf2AywaiiTVpn2yCBJUvK/XZkMln28x2x2dGp+WZ8GNOIUbeoUMHi0tzxpL9J+7wK4rtrxJ...........................] at time 21:52:09.224093
[INFO    ] Running state [vm.swappiness] at time 21:52:09.224312
[INFO    ] Executing state sysctl.present for vm.swappiness
[INFO    ] Executing command 'sysctl -a' in directory '/root'
[INFO    ] Executing command 'sysctl -a' in directory '/root'
[INFO    ] Sysctl value vm.swappiness = 0 is already set
[INFO    ] Completed state [vm.swappiness] at time 21:52:09.292243
[INFO    ] Running state [fs.protected_hardlinks] at time 21:52:09.292465
[INFO    ] Executing state sysctl.present for fs.protected_hardlinks
[INFO    ] Executing command 'sysctl -a' in directory '/root'
[INFO    ] Executing command 'sysctl -a' in directory '/root'
[INFO    ] Sysctl value fs.protected_hardlinks = 1 is already set
[INFO    ] Completed state [fs.protected_hardlinks] at time 21:52:09.353007
[INFO    ] Running state [fs.protected_symlinks] at time 21:52:09.353213
[INFO    ] Executing state sysctl.present for fs.protected_symlinks
[INFO    ] Executing command 'sysctl -a' in directory '/root'
[INFO    ] Executing command 'sysctl -a' in directory '/root'
[INFO    ] Sysctl value fs.protected_symlinks = 1 is already set
[INFO    ] Completed state [fs.protected_symlinks] at time 21:52:09.410497
[INFO    ] Running state [syslog-ng_packages] at time 21:52:09.411279
[INFO    ] Executing state pkg.installed for syslog-ng_packages
[INFO    ] All specified packages are already installed.
[INFO    ] Completed state [syslog-ng_packages] at time 21:52:09.412016
[INFO    ] Running state [rsyslog] at time 21:52:09.412301
[INFO    ] Executing state pkg.purged for rsyslog
[INFO    ] None of the targeted packages are installed or partially installed
[INFO    ] Completed state [rsyslog] at time 21:52:09.412831
[INFO    ] Running state [/etc/default/syslog-ng] at time 21:52:09.412965
[INFO    ] Executing state file.managed for /etc/default/syslog-ng
[INFO    ] File /etc/default/syslog-ng is in the correct state
[INFO    ] Completed state [/etc/default/syslog-ng] at time 21:52:09.415065
[INFO    ] Running state [/etc/logrotate.d/syslog-ng] at time 21:52:09.415203
[INFO    ] Executing state file.managed for /etc/logrotate.d/syslog-ng
[INFO    ] File /etc/logrotate.d/syslog-ng is in the correct state
[INFO    ] Completed state [/etc/logrotate.d/syslog-ng] at time 21:52:09.417225
[INFO    ] Running state [/etc/syslog-ng/syslog-ng.conf] at time 21:52:09.417522
[INFO    ] Executing state file.managed for /etc/syslog-ng/syslog-ng.conf
[INFO    ] File /etc/syslog-ng/syslog-ng.conf is in the correct state
[INFO    ] Completed state [/etc/syslog-ng/syslog-ng.conf] at time 21:52:09.419449
[INFO    ] Running state [/etc/syslog-ng/conf.d/00-common.conf] at time 21:52:09.419746
[INFO    ] Executing state file.managed for /etc/syslog-ng/conf.d/00-common.conf
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://syslog-ng/files/etc/syslog-ng/conf.d/00-common.conf'
[INFO    ] File changed:

---
+++
@@ -3,6 +3,12 @@
 #   THIS FILE IS MANAGED BY SALT, ALL LOCAL EDITS WILL BE OVERWRITTEN !
 #
 # /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\
+
+source s_local {
+   internal();
+   unix-dgram("/dev/log");
+   file("/proc/kmsg" program-override("kernel") flags(kernel));
+};

 filter f_facility_auth { facility(auth, authpriv); };
 filter f_facility_cron { facility(cron); };

[INFO    ] Completed state [/etc/syslog-ng/conf.d/00-common.conf] at time 21:52:09.424061
[INFO    ] Running state [/etc/syslog-ng/conf.d/10-discard.conf] at time 21:52:09.424358
[INFO    ] Executing state file.managed for /etc/syslog-ng/conf.d/10-discard.conf
[INFO    ] File /etc/syslog-ng/conf.d/10-discard.conf is in the correct state
[INFO    ] Completed state [/etc/syslog-ng/conf.d/10-discard.conf] at time 21:52:09.425953
[INFO    ] Running state [/etc/syslog-ng/conf.d/90-default.conf] at time 21:52:09.426247
[INFO    ] Executing state file.managed for /etc/syslog-ng/conf.d/90-default.conf
[INFO    ] File /etc/syslog-ng/conf.d/90-default.conf is in the correct state
[INFO    ] Completed state [/etc/syslog-ng/conf.d/90-default.conf] at time 21:52:09.427734
[INFO    ] Running state [syslog-ng] at time 21:52:09.427867
[INFO    ] Executing state service.running for syslog-ng
[INFO    ] Executing command 'runlevel' in directory '/root'
[INFO    ] Executing command 'service syslog-ng status' in directory '/root'
[INFO    ] The service syslog-ng is already running
[INFO    ] Completed state [syslog-ng] at time 21:52:09.442683
[INFO    ] Running state [tmux] at time 21:52:09.442854
[INFO    ] Executing state pkg.installed for tmux
[INFO    ] Package tmux is already installed.
[INFO    ] Completed state [tmux] at time 21:52:09.443565
[INFO    ] Running state [/etc/tmux.conf] at time 21:52:09.443903
[INFO    ] Executing state file.managed for /etc/tmux.conf
[INFO    ] File /etc/tmux.conf is in the correct state
[INFO    ] Completed state [/etc/tmux.conf] at time 21:52:09.446387
[INFO    ] Running state [vim-nox] at time 21:52:09.446515
[INFO    ] Executing state pkg.installed for vim-nox
[INFO    ] Package vim-nox is already installed.
[INFO    ] Completed state [vim-nox] at time 21:52:09.446995
[INFO    ] Running state [/etc/vim/vimrc.local] at time 21:52:09.447402
[INFO    ] Executing state file.managed for /etc/vim/vimrc.local
[INFO    ] File /etc/vim/vimrc.local is in the correct state
[INFO    ] Completed state [/etc/vim/vimrc.local] at time 21:52:09.449561
[INFO    ] Running state [Europe/Paris] at time 21:52:09.449699
[INFO    ] Executing state timezone.system for Europe/Paris
[INFO    ] Executing command 'grep "UTC=" /etc/default/rcS | grep -vE "^#"' in directory '/root'
[INFO    ] Executing command 'tail -n 1 /etc/adjtime' in directory '/root'
[INFO    ] Timezone Europe/Paris already set, UTC already set to Europe/Paris
[INFO    ] Completed state [Europe/Paris] at time 21:52:09.459954
[INFO    ] Running state [tools] at time 21:52:09.460122
[INFO    ] Executing state pkg.installed for tools
[INFO    ] All specified packages are already installed.
[INFO    ] Completed state [tools] at time 21:52:09.460909
[INFO    ] Running state [salt-master] at time 21:52:09.461029
[INFO    ] Executing state pkg.installed for salt-master
[INFO    ] Version 2014.7.0+ds-2~bpo70+1 of package 'salt-master' is already installed.
[INFO    ] Completed state [salt-master] at time 21:52:09.461495
[INFO    ] Running state [salt-master] at time 21:52:09.461614
[INFO    ] Executing state service.running for salt-master
[INFO    ] Executing command 'runlevel' in directory '/root'
[INFO    ] Executing command 'service salt-master status' in directory '/root'
[INFO    ] The service salt-master is already running
[INFO    ] Completed state [salt-master] at time 21:52:09.475876
[INFO    ] Running state [/etc/salt/master] at time 21:52:09.476045
[INFO    ] Executing state file.managed for /etc/salt/master
[INFO    ] File /etc/salt/master is in the correct state
[INFO    ] Completed state [/etc/salt/master] at time 21:52:09.478707
local:
----------
          ID: packages.*********.fr.wheezy
    Function: pkgrepo.managed
        Name: deb http://packages.*********.fr/ wheezy main
      Result: True
     Comment: Package repo 'deb http://packages.*********.fr/ wheezy main' already configured
     Started: 21:52:08.498498
    Duration: 40.742 ms
     Changes:
----------
          ID: aptitude
    Function: pkg.installed
      Result: True
     Comment: Package aptitude is already installed.
     Started: 21:52:08.539399
    Duration: 203.651 ms
     Changes:
----------
          ID: /etc/apt/apt.conf.d/70debconf
    Function: file.managed
      Result: True
     Comment: File /etc/apt/apt.conf.d/70debconf is in the correct state
     Started: 21:52:08.743248
    Duration: 2.209 ms
     Changes:
----------
          ID: bash-completion
    Function: pkg.installed
      Result: True
     Comment: Package bash-completion is already installed.
     Started: 21:52:08.745585
    Duration: 0.479 ms
     Changes:
----------
          ID: /etc/bash.bashrc
    Function: file.managed
      Result: True
     Comment: File /etc/bash.bashrc is in the correct state
     Started: 21:52:08.746188
    Duration: 2.07 ms
     Changes:
----------
          ID: less
    Function: pkg.installed
      Result: True
     Comment: Package less is already installed.
     Started: 21:52:08.748392
    Duration: 0.484 ms
     Changes:
----------
          ID: /etc/profile.d/less.sh
    Function: file.managed
      Result: True
     Comment: File /etc/profile.d/less.sh updated
     Started: 21:52:08.749193
    Duration: 325.699 ms
     Changes:
              ----------
              diff:
                  New file
              mode:
                  0644
----------
          ID: /etc/motd
    Function: file.managed
      Result: True
     Comment: File /etc/motd is in the correct state
     Started: 21:52:09.075189
    Duration: 3.187 ms
     Changes:
----------
          ID: openntpd
    Function: pkg.installed
      Result: True
     Comment: Package openntpd is already installed.
     Started: 21:52:09.078657
    Duration: 1.123 ms
     Changes:
----------
          ID: /etc/openntpd/ntpd.conf
    Function: file.managed
      Result: True
     Comment: File /etc/openntpd/ntpd.conf is in the correct state
     Started: 21:52:09.080043
    Duration: 2.963 ms
     Changes:
----------
          ID: openssh-server
    Function: pkg.installed
      Result: True
     Comment: Package openssh-server is already installed.
     Started: 21:52:09.083289
    Duration: 1.046 ms
     Changes:
----------
          ID: /etc/ssh/sshd_config
    Function: file.managed
      Result: True
     Comment: File /etc/ssh/sshd_config is in the correct state
     Started: 21:52:09.084595
    Duration: 8.559 ms
     Changes:
----------
          ID: salt-minion
    Function: pkg.installed
      Result: True
     Comment: Version 2014.7.0+ds-2~bpo70+1 of package 'salt-minion' is already installed.
     Started: 21:52:09.093412
    Duration: 0.942 ms
     Changes:
----------
          ID: salt-minion
    Function: service.running
      Result: True
     Comment: The service salt-minion is already running
     Started: 21:52:09.094595
    Duration: 23.583 ms
     Changes:
----------
          ID: /etc/salt/minion
    Function: file.managed
      Result: True
     Comment: File /etc/salt/minion updated
     Started: 21:52:09.118479
    Duration: 18.875 ms
     Changes:
              ----------
              diff:
                  ---
                  +++
                  @@ -10,7 +10,7 @@
                   # Per default the minion will automatically include all config files
                   # from minion.d/*.conf (minion.d is a directory in the same directory
                   # as the main minion config file).
                  -#default_include: minion.d/*.conf
                  +default_include: minion.d/*.conf

                   # Set the location of the salt master server, if the master server cannot be
                   # resolved, then the minion will fail to start.

----------
          ID: ssh_keys_for_root
    Function: ssh_auth.present
        Name: AAAAB3NzaC1yc2EAAAABIwAAAQEAvblupjNT3ctwB4Y3fylHRiNe1ObWipEfy/aYNx7lfFwJKM+3Ub0tqhUHxaG8sacgPKxB5bt2QVY7RavtGe+5UDg80QLCSfkbEgp8tr/.........................
      Result: True
     Comment: The authorized host key AAAAB3NzaC1yc2EAAAABIwAAAQEAvblupjNT3ctwB4Y3fylHRiNe1ObWipEfy/aYNx7lfFwJKM+3Ub0tqhUHxaG8sacgPKxB5bt2QVY7RavtGe+5UDg80QLCSfkbEgp8tr/...................... is already present for user root
     Started: 21:52:09.137587
    Duration: 2.163 ms
     Changes:
----------
          ID: sysctl_kernel.dmesg_restrict
    Function: sysctl.present
        Name: kernel.dmesg_restrict
      Result: True
     Comment: Sysctl value kernel.dmesg_restrict = 1 is already set
     Started: 21:52:09.140012
    Duration: 82.066 ms
     Changes:
----------
          ID: ssh_keys_for_root
    Function: ssh_auth.present
        Name: AAAAB3NzaC1yc2EAAAADAQABAAABAQDFh6kfcJ7wf2AywaiiTVpn2yCBJUvK/XZkMln28x2x2dGp+WZ8GNOIUbeoUMHi0tzxpL9J+7wK4rtrxJ93cpU1ECBS1G....................
      Result: True
     Comment: The authorized host key AAAAB3NzaC1yc2EAAAADAQABAAABAQDFh6kfcJ7wf2AywaiiTVpn2yCBJUvK/XZkMln28x2x2dGp+WZ8GNOIUbeoUMHi0tzxpL9J+7wK4rtrxJ93cpU1ECBS1G.................... is already present for user root
     Started: 21:52:09.222349
    Duration: 1.744 ms
     Changes:
----------
          ID: sysctl_vm.swappiness
    Function: sysctl.present
        Name: vm.swappiness
      Result: True
     Comment: Sysctl value vm.swappiness = 0 is already set
     Started: 21:52:09.224312
    Duration: 67.931 ms
     Changes:
----------
          ID: sysctl_fs.protected_hardlinks
    Function: sysctl.present
        Name: fs.protected_hardlinks
      Result: True
     Comment: Sysctl value fs.protected_hardlinks = 1 is already set
     Started: 21:52:09.292465
    Duration: 60.542 ms
     Changes:
----------
          ID: sysctl_fs.protected_symlinks
    Function: sysctl.present
        Name: fs.protected_symlinks
      Result: True
     Comment: Sysctl value fs.protected_symlinks = 1 is already set
     Started: 21:52:09.353213
    Duration: 57.284 ms
     Changes:
----------
          ID: syslog-ng_packages
    Function: pkg.installed
      Result: True
     Comment: All specified packages are already installed.
     Started: 21:52:09.411279
    Duration: 0.737 ms
     Changes:
----------
          ID: rsyslog
    Function: pkg.purged
      Result: True
     Comment: None of the targeted packages are installed or partially installed
     Started: 21:52:09.412301
    Duration: 0.53 ms
     Changes:
----------
          ID: /etc/default/syslog-ng
    Function: file.managed
      Result: True
     Comment: File /etc/default/syslog-ng is in the correct state
     Started: 21:52:09.412965
    Duration: 2.1 ms
     Changes:
----------
          ID: /etc/logrotate.d/syslog-ng
    Function: file.managed
      Result: True
     Comment: File /etc/logrotate.d/syslog-ng is in the correct state
     Started: 21:52:09.415203
    Duration: 2.022 ms
     Changes:
----------
          ID: /etc/syslog-ng/syslog-ng.conf
    Function: file.managed
      Result: True
     Comment: File /etc/syslog-ng/syslog-ng.conf is in the correct state
     Started: 21:52:09.417522
    Duration: 1.927 ms
     Changes:
----------
          ID: /etc/syslog-ng/conf.d/00-common.conf
    Function: file.managed
      Result: True
     Comment: File /etc/syslog-ng/conf.d/00-common.conf updated
     Started: 21:52:09.419746
    Duration: 4.315 ms
     Changes:
              ----------
              diff:
                  ---
                  +++
                  @@ -3,6 +3,12 @@
                   #   THIS FILE IS MANAGED BY SALT, ALL LOCAL EDITS WILL BE OVERWRITTEN !
                   #
                   # /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\ /!\
                  +
                  +source s_local {
                  + internal();
                  + unix-dgram("/dev/log");
                  + file("/proc/kmsg" program-override("kernel") flags(kernel));
                  +};

                   filter f_facility_auth { facility(auth, authpriv); };
                   filter f_facility_cron { facility(cron); };

----------
          ID: /etc/syslog-ng/conf.d/10-discard.conf
    Function: file.managed
      Result: True
     Comment: File /etc/syslog-ng/conf.d/10-discard.conf is in the correct state
     Started: 21:52:09.424358
    Duration: 1.595 ms
     Changes:
----------
          ID: /etc/syslog-ng/conf.d/90-default.conf
    Function: file.managed
      Result: True
     Comment: File /etc/syslog-ng/conf.d/90-default.conf is in the correct state
     Started: 21:52:09.426247
    Duration: 1.487 ms
     Changes:
----------
          ID: syslog-ng
    Function: service.running
      Result: True
     Comment: The service syslog-ng is already running
     Started: 21:52:09.427867
    Duration: 14.816 ms
     Changes:
----------
          ID: tmux
    Function: pkg.installed
      Result: True
     Comment: Package tmux is already installed.
     Started: 21:52:09.442854
    Duration: 0.711 ms
     Changes:
----------
          ID: /etc/tmux.conf
    Function: file.managed
      Result: True
     Comment: File /etc/tmux.conf is in the correct state
     Started: 21:52:09.443903
    Duration: 2.484 ms
     Changes:
----------
          ID: vim-nox
    Function: pkg.installed
      Result: True
     Comment: Package vim-nox is already installed.
     Started: 21:52:09.446515
    Duration: 0.48 ms
     Changes:
----------
          ID: /etc/vim/vimrc.local
    Function: file.managed
      Result: True
     Comment: File /etc/vim/vimrc.local is in the correct state
     Started: 21:52:09.447402
    Duration: 2.159 ms
     Changes:
----------
          ID: timezone
    Function: timezone.system
        Name: Europe/Paris
      Result: True
     Comment: Timezone Europe/Paris already set, UTC already set to Europe/Paris
     Started: 21:52:09.449699
    Duration: 10.255 ms
     Changes:
----------
          ID: tools
    Function: pkg.installed
      Result: True
     Comment: All specified packages are already installed.
     Started: 21:52:09.460122
    Duration: 0.787 ms
     Changes:
----------
          ID: salt-master
    Function: pkg.installed
      Result: True
     Comment: Version 2014.7.0+ds-2~bpo70+1 of package 'salt-master' is already installed.
     Started: 21:52:09.461029
    Duration: 0.466 ms
     Changes:
----------
          ID: salt-master
    Function: service.running
      Result: True
     Comment: The service salt-master is already running
     Started: 21:52:09.461614
    Duration: 14.262 ms
     Changes:
----------
          ID: /etc/salt/master
    Function: file.managed
      Result: True
     Comment: File /etc/salt/master is in the correct state
     Started: 21:52:09.476045
    Duration: 2.662 ms
     Changes:

Summary
-------------
Succeeded: 39 (changed=3)
Failed:     0
-------------
Total states run:     39
root@tools-1:~#

I observed this behaviour on both 2014.1.11 and the new 2014.7.0, and it is reproducible every time. Am I missing something or is it possibly a bug?

[basepi]

So unless I'm missing something, your output looks correct. /etc/profile.d/less.sh reports changes to be made in the test run, and makes those changes in the main run. The other two changed states in your main run do not have output in your test run, so it seems you're running different sets of states in your test=True run from your main run.

[falzm]

No, the change set is exactly the same between the 2 runs. The changes I made up for this example are the /etc/profile.d/less.sh file removed, and /etc/syslog-ng/conf.d/00-common.conf and /etc/salt/minion files content edited – which are 3 differents states –, and only the change related to /etc/profile.d/less.sh appears.

[basepi]

So you're saying that the test=True mode is truncating something like 3/4 of your states' output? That's _very_ strange.

[falzm]

That's what it looks like, yes. I'm quite new to Salt so I'm not entirely sure I haven't done something, wrong, however I haven't tweaked the stock configuration a lot and since I encounter this behaviour on different setups and different versions of Salt...

I can try to reproduce this issue on a completely vanilla setup, if you want.

[basepi]

That would be great. It would also be useful to see if we can create a much smaller test case for reproduction purposes. This is definitely not one I've ever seen before.

[falzm]

Colton

I can't reproduce this issue on a vanilla setup with 2014.7.0, so I guess I must have done something wrong with my current setup configuration. Sorry for the false alarm :)

[warrenhouzz]

Hi Marc,

Did you ever find the cause ? I am facing a similar situation where test=True is giving me less changes than actual run. Any insight will be very helpful ! I am using 2014.7.1 (Helium).

[warrenhouzz]

Looks like this could be related to the "failhard" option in the minion/master settings. Once I removed all references to the "failhard" option in my master, minion, & state files, changes shown under test=True and the actual run are finally consistent. Not exactly sure why this is happening.

[falzm]

Hi Warren

No I didn't find out the cause, but I do use the failhard setting so I might try to disable it to see if it's related to this issue. I'll keep you posted.

[falzm]

@warrenhouzz, @basepi,

I confirm that this issue is correlated with setting master's failhard option to True: once reset to default value False I can see all changes to be applied using test=True option. Thank you very much for pointing that out!

[basepi]

Interesting. I wonder if failhard is failing when the return is None as well as when it's False. Thanks for the update.

[ryan-lane]

Hey. This is still a problem, and it's really, really annoying for people that use failhard. Is there any update here?

[meggiebot]

Would like to get this fixed for 2016.3.4

[thatch45]

I pushed a fix but the question is, should we globally disable failhard when running test=True? what do you think @ryan-lane ?

[ryan-lane]

hm. maybe that's a good idea. It's actually pretty difficult to ensure that failhard isn't going to fail in weird ways during a dry run and what you really want to see is the result from all of the states.

[thatch45]

It almost makes we wonder if we should have an ignore_failhard flag, but a test=True should logically not make changes, but in a failhard environment I think it is even harder since you likely have a higher chance of later states failing anyway.
Let me know what you think

[ryan-lane]

I think it's likely best to ignore it for dry-run. We don't really test states very well for dry-run return values. A lot of states return False when they should probably return true. Also, in some cases it's really difficult for states to return anything other than false, because a change from a previous dependency state hasn't occurred.