Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

lsattr slowing down archive.extracted #47043

Open
xBytez opened this issue Apr 12, 2018 · 10 comments

Comments

Projects
None yet
8 participants
@xBytez
Copy link

commented Apr 12, 2018

Description of Issue/Question

When using archive.extracted with user and group set, it loops through every file checking it's attributes, this is both ineffecient and slow. It makes my CPU usage peak and my states takes a solid 10 minutes to run.

What I'd like:

  • An option to turn the lsattr stuff off and just enforce the chown.
  • Rewrite the lsattr stuff to be more efficient (example: lsattr -R /var/folder)

Setup

(Please provide relevant configs and/or SLS files (Be sure to remove sensitive info).)

  archive.extracted:
    - name: /var/folder
    - source: s3://bucket/filename
    - skip_verify: True
    - user: user
    - group: user

Steps to Reproduce Issue

(Include debug logs if possible and relevant.)

2018-04-12 23:11:01,923 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/resolve-pkg/package.json
2018-04-12 23:11:02,108 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/resolve-pkg/index.js'] in directory '/root'
2018-04-12 23:11:02,517 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/resolve-pkg/index.js
2018-04-12 23:11:02,519 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/History.md'] in directory '/root'
2018-04-12 23:11:03,133 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/History.md
2018-04-12 23:11:03,135 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/engine.io.js'] in directory '/root'
2018-04-12 23:11:03,704 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/engine.io.js
2018-04-12 23:11:03,707 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/README.md'] in directory '/root'
2018-04-12 23:11:04,280 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/README.md
2018-04-12 23:11:04,282 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/package.json'] in directory '/root'
2018-04-12 23:11:04,750 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/package.json
2018-04-12 23:11:04,832 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/LICENSE'] in directory '/root'
2018-04-12 23:11:05,509 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/LICENSE
2018-04-12 23:11:05,611 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/index.js'] in directory '/root'
2018-04-12 23:11:06,207 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/index.js
2018-04-12 23:11:06,308 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/lib/xmlhttprequest.js'] in directory '/root'
2018-04-12 23:11:06,639 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/lib/xmlhttprequest.js
2018-04-12 23:11:06,718 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/lib/transport.js'] in directory '/root'
2018-04-12 23:11:07,315 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/lib/transport.js
2018-04-12 23:11:07,395 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/lib/socket.js'] in directory '/root'
2018-04-12 23:11:07,865 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/lib/socket.js
2018-04-12 23:11:07,867 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/lib/index.js'] in directory '/root'
2018-04-12 23:11:08,459 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/lib/index.js
2018-04-12 23:11:08,482 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/lib/transports/polling-xhr.js'] in directory '/root'
2018-04-12 23:11:09,238 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/lib/transports/polling-xhr.js
2018-04-12 23:11:09,240 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/lib/transports/websocket.js'] in directory '/root'
2018-04-12 23:11:09,650 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/lib/transports/websocket.js
2018-04-12 23:11:09,668 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/lib/transports/polling-jsonp.js'] in directory '/root'
2018-04-12 23:11:10,179 [salt.loaded.int.module.cmdmod:282 ][DEBUG   ][21519] output: --------------e---- /var/folder/node_modules/engine.io-client/lib/transports/polling-jsonp.js
2018-04-12 23:11:10,181 [salt.loaded.int.module.cmdmod:385 ][INFO    ][21519] Executing command [u'lsattr', u'/var/folder/node_modules/engine.io-client/lib/transports/polling.js'] in directory '/root'

Versions Report

(Provided by running salt --versions-report. Please also mention any differences in master/minion versions.)

Master:

Salt Version:
           Salt: 2018.3.0

Dependency Versions:
           cffi: 1.11.4
       cherrypy: unknown
       dateutil: 2.6.1
      docker-py: Not Installed
          gitdb: 2.0.0
      gitpython: 2.1.1
          ioflo: Not Installed
         Jinja2: 2.7.2
        libgit2: 0.24.5
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: 0.9.1
   msgpack-pure: Not Installed
 msgpack-python: 0.4.8
   mysql-python: Not Installed
      pycparser: 2.18
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: 0.24.2
         Python: 2.7.13 (default, Nov 24 2017, 17:33:09)
   python-gnupg: Not Installed
         PyYAML: 3.11
          PyZMQ: 16.0.2
           RAET: Not Installed
          smmap: 2.0.1
        timelib: Not Installed
        Tornado: 4.5.3
            ZMQ: 4.1.6

System Versions:
           dist: debian 9.4
         locale: UTF-8
        machine: x86_64
        release: 4.9.0-6-amd64
         system: Linux
        version: debian 9.4

Minion:

Salt Version:
           Salt: 2018.3.0

Dependency Versions:
           cffi: 1.11.4
       cherrypy: Not Installed
       dateutil: 2.2
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.7.2
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: 0.9.1
   msgpack-pure: Not Installed
 msgpack-python: 0.4.8
   mysql-python: Not Installed
      pycparser: 2.18
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 2.7.13 (default, Nov 24 2017, 17:33:09)
   python-gnupg: Not Installed
         PyYAML: 3.11
          PyZMQ: 16.0.2
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.5.3
            ZMQ: 4.1.6

System Versions:
           dist: debian 9.4
         locale: UTF-8
        machine: x86_64
        release: 4.9.0-6-amd64
         system: Linux
        version: debian 9.4

Please feel free to ask for any more info if this isn't sufficient.

@garethgreenaway

This comment has been minimized.

Copy link
Member

commented Apr 13, 2018

@xBytez Thanks for the report. Ideally we would want to ensure the lsattr portion is being as efficient as possible.

@rmarchei

This comment has been minimized.

Copy link
Contributor

commented Jun 14, 2018

There's a similar issue with other states as well (i.e: with file.directory and recursive permissions).
States that used to take seconds can now take 10 mins to complete.

@Gabri-connect

This comment has been minimized.

Copy link

commented Jul 3, 2018

I have this issue as well. If I run file.directory or anything specifying user + group, lsattr runs forever.
35 min if I have several file.directory calls.
COuld we get an update on this please?

@sastorsl

This comment has been minimized.

Copy link
Contributor

commented Sep 21, 2018

Can confirm. With debug on you get 38865 log lines for 13254 files and spent close to two minutes.
Example:

# setup
rm -rf /tmp/foo && mkdir -p /tmp/foo/bar/bat && find /tmp/foo -type d -exec cp /dev/null {}/file.txt \;

# run
salt-call -l debug state.single file.directory /tmp/foo user=root group=root dir_mode=750 makedirs=True file_mode=644 recurse="['user', 'group', 'mode']"

# output
...
[INFO    ] Executing command [u'lsattr', u'/tmp/foo/file.txt'] in directory '/root'
[DEBUG   ] stdout: ---------------- /tmp/foo/file.txt
[DEBUG   ] output: ---------------- /tmp/foo/file.txt
[INFO    ] Executing command [u'lsattr', u'/tmp/foo/bar/file.txt'] in directory '/root'
[DEBUG   ] stdout: ---------------- /tmp/foo/bar/file.txt
[DEBUG   ] output: ---------------- /tmp/foo/bar/file.txt
...

Can this be fixed by adding output_loglevel=warn (or similar) in "file.lsattr"s call to cmd.run. This or a loglevel parameter for file.lsattr - which toggles cmd.run debug level?

Not sure of what the author of file.lsattr had in mind, but maybe @terminalmage can have a look?

@sergeyfd

This comment has been minimized.

Copy link

commented Jan 3, 2019

This is really bad. Are there any plans to have it fixed?

@sergeyfd

This comment has been minimized.

Copy link

commented Jan 3, 2019

The problem is in this block in file.py. This enforcement is extremely expensive for directories with many files. It should be optional, I think.

 `if not salt.utils.platform.is_windows() and not is_dir and not is_link:
    try:
        lattrs = lsattr(name)
    except SaltInvocationError:
        lattrs = None
    if lattrs is not None:
        # List attributes on file
        perms['lattrs'] = ''.join(lattrs.get(name, ''))
        # Remove attributes on file so changes can be enforced.
        if perms['lattrs']:
            chattr(name, operator='remove', attributes=perms['lattrs'])`
@terminalmage

This comment has been minimized.

Copy link
Contributor

commented Jan 3, 2019

Fixed in #51044.

@sergeyfd

This comment has been minimized.

Copy link

commented Jan 3, 2019

Thanks, that makes total sense.

@mchugh19

This comment has been minimized.

Copy link
Contributor

commented Mar 3, 2019

Is this still an open issue?

@sergeyfd

This comment has been minimized.

Copy link

commented Mar 9, 2019

No, it can be closed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.