Salt: pkg.installed fails on installing from HTTPS rpm source

[danlsgiga]

Description of Issue/Question

I have a formula that installs the Graylog repo package from its https source url. It worked fine until I upgraded Salt to 2017.7.0 this week.

Setup

graylog.repo:
  pkg.installed:
    - sources:
      - graylog-2.2-repository: 'https://packages.graylog2.org/repo/packages/graylog-2.3-repository_latest.rpm'

Steps to Reproduce Issue

Please use the docker container created to reproduce the issue.

docker run -it danlsgiga/salt-pkg-http:2017.7.0

It returns with the following error but works just fine from curl or any browser:

[ERROR   ] Uncaught exception
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/tornado/http1connection.py", line 184, in _read_message
    header_future = delegate.headers_received(start_line, headers)
  File "/usr/lib64/python2.7/site-packages/tornado/simple_httpclient.py", line 457, in headers_received
    self.request.header_callback('%s %s %s\r\n' % first_line)
  File "/usr/lib64/python2.7/site-packages/tornado/stack_context.py", line 274, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/salt/fileclient.py", line 626, in on_header
    write_body[1].parse_line(hdr)  # pylint: disable=no-member
  File "/usr/lib64/python2.7/site-packages/tornado/httputil.py", line 188, in parse_line
    name, value = line.split(":", 1)
ValueError: need more than 1 value to unpack
[ERROR   ] Exception in callback <functools.partial object at 0x23040a8>
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/tornado/ioloop.py", line 591, in _run_callback
    ret = callback()
  File "/usr/lib64/python2.7/site-packages/tornado/stack_context.py", line 342, in wrapped
    raise_exc_info(exc)
  File "/usr/lib64/python2.7/site-packages/tornado/stack_context.py", line 313, in wrapped
    ret = fn(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/tornado/simple_httpclient.py", line 400, in <lambda>
    lambda f: f.result())
  File "/usr/lib64/python2.7/site-packages/tornado/concurrent.py", line 214, in result
    raise_exc_info(self._exc_info)
  File "/usr/lib64/python2.7/site-packages/tornado/gen.py", line 879, in run
    yielded = self.gen.send(value)
  File "/usr/lib64/python2.7/site-packages/tornado/http1connection.py", line 186, in _read_message
    yield header_future
  File "/usr/lib64/python2.7/site-packages/tornado/http1connection.py", line 54, in __exit__
    raise _QuietException
_QuietException
[ERROR   ] An error was encountered while installing package(s): Error: HTTP 599: Connection closed reading https://packages.graylog2.org/repo/packages/graylog-2.3-repository_latest.rpm
local:
----------
          ID: graylog.repo
    Function: pkg.installed
      Result: False
     Comment: An error was encountered while installing package(s): Error: HTTP 599: Connection closed reading https://packages.graylog2.org/repo/packages/graylog-2.3-repository_latest.rpm
     Started: 14:51:02.811192
    Duration: 16953.582 ms
     Changes:

Summary for local
------------
Succeeded: 0
Failed:    1
------------
Total states run:     1
Total run time:  16.954 s

Versions Report

Salt Version:
           Salt: 2017.7.0

Dependency Versions:
           cffi: Not Installed
       cherrypy: unknown
       dateutil: 2.5.3
      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: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.8
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: 3.4.3
         pygit2: Not Installed
         Python: 2.7.5 (default, Nov  6 2016, 00:28:07)
   python-gnupg: Not Installed
         PyYAML: 3.11
          PyZMQ: 15.3.0
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.1.4

System Versions:
           dist: centos 7.3.1611 Core
         locale: UTF-8
        machine: x86_64
        release: 3.10.0-514.26.2.el7.x86_64
         system: Linux
        version: CentOS Linux 7.3.1611 Core

[garethgreenaway]

@danlsgiga Thanks for the report and the docker image for testing. Based on the stack trace, this appears to be a failure in the tornado library. Are you able to tell if prior to the upgrade you were using a different version of python-tornado?

[danlsgiga]

Hi @garethgreenaway, as far as I can see the python-tornado I have is the following one and it hasn't been updated along with Salt as per my yum.log records:

python-tornado-4.2.1-1.el7.x86_64

Hope it helps!

[garethgreenaway]

@danlsgiga I was able to duplicate this and found the spot where the code is breaking. We'll get a fix out asap.

[terminalmage]

Disregard this comment, the actual cause has been identified and fixed. See https://github.com/saltstack/salt/issues/42941#issuecomment-322658690.

This is happening because the remote server is closing the connection. While tornado is processing the headers from the GET request, while stepping through with a debugger I was able to see a header line consisting of Connection: close\r\n. For 302 redirects we should be seeing a Connection: keep-alive\r\n here.

I'm not sure if this is a bug in tornado, or something we're doing wrong in using tornado to download files.

[terminalmage]

For what it's worth, I was able to download the file just fine using cURL while manually setting the User-agent to the one used by Salt. So, this does not appear to be the result of User-agent checking being done by the remote server.

[terminalmage]

You can reproduce this without needing the SLS, simply by calling cp.cache_file https://packages.graylog2.org/repo/packages/graylog-2.3-repository_latest.rpm

[terminalmage]

I will do a git bisect in the morning, assuming I can find a working commit.

[terminalmage]

Actually, ignore my earlier comment about the connection being closed. I've found the actual problem and will have a fix in soon.

[terminalmage]

Fix has been submitted in https://github.com/saltstack/salt/pull/42967.

[danlsgiga]

This is freaking awesome guys @terminalmage and @garethgreenaway! Fantastic job and thanks a lot! I'll place this fix in my _states folder and use it until 2017.7.2 is out!

[terminalmage]

@danlsgiga The fix was in salt/fileclient.py, I don't think you'll be able to cleanly apply it using that method.

[danlsgiga]

Thanks, @terminalmage! I just figured this and was about to comment here. Is there any way to load the fixed fileclient.py in all minions the same way we do with dynamic modules / states / etc? Just trying to avoid having to hard replace it in all minions and the master.

[terminalmage]

@danlsgiga Unfortunately not. The fileclient is not extensible in the same way that modules/states/etc. are.

[danlsgiga]

No problem!! I think I will just wait 2017.7.2 to come out and download the artifact locally in the meantime. Thanks!

[terminalmage]

Sure, no prob. Thanks for finding and reporting this, it was good to get it identified and fixed.