Different hashtype between master and minion should result in warning

[Mrten]

I've got a tree that I'm distributing via salt and it makes a highstate run very slow.

static-web:
  file.recurse:
    - name: /var/www/static/
    - source: salt://static_web/ # staat in /home/salt/files
#    - clean: true   # eens per zoveel tijd runnen want het scheelt een boel
    - group: www-data
    - dir_mode: 755
    - file_mode: 644
    - include_empty: true

when I up the log_level to profile:

2016-11-30 14:39:30,662 [salt.state       ][INFO    ][12520] Completed state [/var/www/static/] at time 14:39:30.662156 duration_in_ms=54343.841

When run over a slow line (4mbit) it is totally unacceptable, highstate times up to 1800 secs.

If I look at the logs it seems that all files are redistributed all the time. This seems to be a regression in 2016.3.4 (my current version), didn't happen before.

[Ch3LL]

@Mrten which version was this previously working on? I know there is this issue currenlty open: #11167 which documents the slow performance of file.recurse due to it checking each file for permissions.

Is that what you are seeing or are you saying the files are re-copied over each time?

[Mrten]

My last version was 2015.8.12. I think I'm seeing all files being recopied all the time, this is from a minion's log for a highstate:

2016-11-30 14:38:36,319 [salt.state       ][INFO    ][12520] Running state [/var/www/static/] at time 14:38:36.318315
2016-11-30 14:38:36,319 [salt.state       ][INFO    ][12520] Executing state file.recurse for /var/www/static/
2016-11-30 14:38:36,475 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../animation_opacity.css'
2016-11-30 14:38:36,489 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../lightbulb01.320x180.jpg'
2016-11-30 14:38:36,503 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../lightbulb03.320x180.jpg'
2016-11-30 14:38:36,517 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../lightbulb05.320x180.jpg'
2016-11-30 14:38:36,530 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../lightbulb07.320x180.jpg'
2016-11-30 14:38:36,544 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../lightbulb09.320x180.jpg'
2016-11-30 14:38:36,557 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../index.php'
2016-11-30 14:38:37,606 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../schaatsen.m4v'
2016-11-30 14:38:38,235 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../ophetijs.m4v'
2016-11-30 14:38:39,478 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../Tjeukemeer.m4v'
2016-11-30 14:38:39,842 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../verjaardag.1.m4v'
2016-11-30 14:38:40,242 [salt.fileclient  ][INFO    ][12520] Fetching file from saltenv 'base', ** done ** 'static_web/.../verjaardag.2.m4v'

Notice how the large .m4v's take the most of the time.

And another clue is that I'm seeing traffic peaks while running a highstate.

[Mrten]

The Info Needed tag can be removed...

[Ch3LL]

@Mrten i'm having a hard time replicating this.

Here is a docker container with my test case:

1. docker run -it -v /home/ch3ll/git/salt/:/testing/ ch3ll/issues:37992 (where /home/ch3ll/git/salt is a local cloned git repo of salt)
2. salt-call --local state.apply test -lprofile

And you will see the messages:

[INFO ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://static_web/test17.m4v' so it sees its already in cache.

I'm wondering if there was an issue when you upgraded. If you delete the cache master and minion side do you see the correct behavior?

[Mrten]

How to I delete the cache on master and minion, just to be sure? empty out /var/cache/salt?

[Mrten]

Removed both /var/cache/salt/master and /minion, restarted salt-master and the minion, still seeing the same.

[Mrten]

This is 2016.3.4 on both sides, not the latest salt, hope you're using the same version.

[Mrten]

Even does so if I comment out include_empty, and when I run with state.sls

[Mrten]

I am finding the static_web/ dir in /var/cache/salt/minion/files/base on the minion, not in /var/cache/salt/minion/files/static_web where I'd expect it?

[Mrten]

From the master config:

file_roots:
  base:
    - /home/salt/conf
    - /home/salt/files

So the static_web in base is expected.

[Mrten]

Got it: in fileclient.py the server is using sha1 hashes, and the client is using sha256 hashes.

[Mrten]

With this diff:

--- fileclient.py-orig	2016-12-20 14:29:33.038671618 +0100
+++ fileclient.py	2016-12-20 14:30:32.873655774 +0100
@@ -1127,6 +1127,9 @@

         if dest2check and os.path.isfile(dest2check):
             hash_local = self.hash_file(dest2check, saltenv)
+            log.debug(
+              'local_hash: {0}, hash_server: {1}'.format(hash_local, hash_server)
+            )
             if hash_local == hash_server:
                 log.info(
                     'Fetching file from saltenv \'{0}\', ** skipped ** '

I get loglines like:

2016-12-20 14:31:44,359 [salt.fileclient  ][DEBUG   ][20051] local_hash: {'hsum': '3409242778b83aa8b9611589951beac1b70a4e5c1f4dc9780ac59fbefcb36f2b', 'hash_type': 'sha256'}, hash_server: {'hsum': '1d0b430b24c174f482509350627399cb002304ce', 'hash_type': 'sha1'}