Salt: minion proxy settings causing http GETs to fail in consul module

[campbellmc]

Description of Issue/Question

Trivial consul module GET requests fail when proxy is enabled, and when run in a state after a file managed with remotefs:

2017-09-27 15:34:04,283 [salt.state ][ERROR ][27010] 'consul.agent_info' failed: initialize() got an unexpected keyword argument 'max_body_size'

I don't believe it's actually a consul module problem - it appears more to do with tornado not closing or re-initialising for subsequent http requests in a state file.

Setup

Minions have proxy configuration (including no_proxy)
PR Feature add no proxy support #43764 has been monkey patched on 2017.7.1

Steps to Reproduce Issue

The API call works fine from the command line on the minion:

# curl -X GET --noproxy 127.0.0.1 127.0.0.1:8500/v1/agent/self
{"Config":{"DevMode":false,"Limits":{"RPCRate":1.7976931348623157e+308,"RPCMaxBurst":1000},"Performance":{"RaftMultiplier":0},"Bootstrap":false,"BootstrapExpect":0,"Server":false......

Minions have proxy configuration:

proxy_host: proxy.service.consul
proxy_port: 8080
no_proxy: ["127.0.0.1", "localhost",]

Run agent.self method in a state file:

get_agent_info:
  module.run:
    - consul.agent_self:
      - consul_url: http://127.0.0.1:8500

# salt kevin state.apply consul_test.agent_self
kevin:
13:44:48.715348 [ 51.189 ms]     module.run        Changed   Name: get_agent_info

Summary for kevin
------------
Succeeded: 1 (changed=1)
Failed:    0
------------
Total states run:     1
Total run time:  51.189 ms



md5-4dce4bc20619da7cba031f3848726e4e



test_http_source:
  file.managed:
    - name: /tmp/test.txt
    - source: https://sentry.io
    - skip_verify: True

get_agent_info:
  module.run:
    - consul.agent_self:
      - consul_url: http://127.0.0.1:8500



md5-7c1868e912539299c478436d8ebcf09d



# salt kevin state.apply consul_test.agent_self
kevin:
13:41:40.709597 [1195.605 ms]       file.managed    Changed   Name: /tmp/test.txt
13:41:41.906982 [ 11.617 ms]     module.run        Failed    Name: get_agent_info

Summary for kevin
------------
Succeeded: 1 (changed=1)
Failed:    1
------------
Total states run:     2
Total run time:   1.207 s



md5-81e01197b587e22dafe3b4f28f613a3d



Sep 28 14:16:00 kevin salt-minion: [INFO    ] File /tmp/test.txt is in the correct state
Sep 28 14:16:00 kevin salt-minion: [INFO    ] Completed state [/tmp/test.txt] at time 14:16:00.905680 duration_in_ms=1330.729
Sep 28 14:16:00 kevin salt-minion: [INFO    ] Running state [get_agent_info] at time 14:16:00.907957
Sep 28 14:16:00 kevin salt-minion: [INFO    ] Executing state module.run for [get_agent_info]
Sep 28 14:16:00 kevin salt-minion: Exception AttributeError: "'HTTPClient' object has no attribute '_closed'" in <bound method HTTPClient.__del__ of <tornado.httpclient.HTTPClient object at 0x2b9cc50>> ignored
Sep 28 14:16:00 kevin salt-minion: [ERROR   ] 'consul.agent_self' failed: initialize() got an unexpected keyword argument 'max_body_size'
Sep 28 14:16:00 kevin salt-minion: [INFO    ] Completed state [get_agent_info] at time 14:16:00.918312 duration_in_ms=10.354
Sep 28 14:16:00 kevin salt-minion: [INFO    ] Returning information for job: 20170928141556135853



md5-33f3e55dfc890716e108059c39f3fd32



# salt kevin state.apply consul_test.agent_self
kevin:
13:59:28.886002 [2254.964 ms]       file.managed    Clean     Name: /tmp/test.txt
13:59:31.142339 [ 10.531 ms]     module.run        Changed   Name: get_agent_info

Summary for kevin
------------
Succeeded: 2 (changed=1)
Failed:    0
------------
Total states run:     2
Total run time:   2.265 s



md5-9de40eaf195988618aaa39f429182b61



# salt --versions-report
Salt Version:
           Salt: 2017.7.1

Dependency Versions:
           cffi: 1.6.0
       cherrypy: Not Installed
       dateutil: 2.5.3
      docker-py: Not Installed
          gitdb: 0.6.4
      gitpython: 1.0.1
          ioflo: Not Installed
         Jinja2: 2.7.2
        libgit2: 0.24.6
        libnacl: Not Installed
       M2Crypto: 0.21.1
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.8
   mysql-python: Not Installed
      pycparser: 2.14
       pycrypto: 2.6.1
   pycryptodome: 3.4.3
         pygit2: 0.24.2
         Python: 2.7.5 (default, Aug  4 2017, 00:39:18)
   python-gnupg: 0.3.8
         PyYAML: 3.11
          PyZMQ: 15.3.0
           RAET: Not Installed
          smmap: 0.9.0
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.1.4

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

[Ch3LL]

Any chance you can troubleshoot down to whether its the proxy configurations or the new PR that adds the no_proxy option? A consul that is not local that you would need to proxy through?

[campbellmc]

Yes - I'll give something along these lines a go.
I don't actually think it's the referenced PR at all. I'll try to exclude it.

[campbellmc]

So, I created an alternate proxy service which will proxy requests to a consul service. The consul service has an otherwise unroutable address.

Verify that the new configuration provides access from the command line [OK]:

# curl --proxy http://alternate_proxy:8080 -L consul_private:8500/v1/agent/self
{"Config":{"DevMode":false,"Limits":{"RPCRate.....

Modify the salt minion proxy settings:

id: kevin
log_level: info
master: aaa.bbb.ccc.ddd
# proxy_host: proxy.service.consul
proxy_host: alternate_proxy
proxy_port: 8080
no_proxy: ["127.0.0.1", "localhost",]

Try the to access consul agent via salt consul module with the new consul url:

get_agent_info:
  module.run:
    - consul.agent_self:
      - consul_url: http://consul_private:8500

Fails!

# salt kevin state.apply consul_test.agent_self_proxy
kevin:
22:03:12.951607 [ 13.177 ms]     module.run        Failed    Name: get_agent_info

Summary for kevin
------------
Succeeded: 0
Failed:    1
------------
Total states run:     1
Total run time:  13.177 ms

2017-09-28 22:52:06,740 [salt.fileclient  ][INFO    ][24530] Fetching file from saltenv 'base', ** done ** 'consul_test/agent_self_proxy.sls'
2017-09-28 22:52:06,779 [salt.minion      ][INFO    ][24544] Starting a new job with PID 24544
2017-09-28 22:52:06,794 [salt.state       ][INFO    ][24530] Running state [get_agent_info] at time 22:52:06.793853
2017-09-28 22:52:06,794 [salt.state       ][INFO    ][24530] Executing state module.run for [get_agent_info]
2017-09-28 22:52:06,808 [salt.minion      ][INFO    ][24544] Returning information for job: 20170928225206599136
2017-09-28 22:52:06,829 [salt.utils.decorators][ERROR   ][24530] Unhandled exception occurred in function "run: Body must be None for GET request
2017-09-28 22:52:06,832 [salt.state       ][ERROR   ][24530] An exception occurred in this state: Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/salt/state.py", line 1837, in call
    **cdata['kwargs'])
  File "/usr/lib/python2.7/site-packages/salt/loader.py", line 1794, in wrapper
    return f(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/salt/utils/decorators/__init__.py", line 619, in _decorate
    return self._call_function(kwargs)
  File "/usr/lib/python2.7/site-packages/salt/utils/decorators/__init__.py", line 333, in _call_function
    raise error
ValueError: Body must be None for GET request

2017-09-28 22:52:06,833 [salt.state       ][INFO    ][24530] Completed state [get_agent_info] at time 22:52:06.832966 duration_in_ms=39.12
2017-09-28 22:52:06,839 [salt.minion      ][INFO    ][24530] Returning information for job: 20170928225201329262

Checking proxy logs - no request is received when using consul module.

Remove the no_proxy line from the minion configuration. Same result.

To summarise:

Using curl directly from the shell works in all proxy configurations.

consul module:

• works fine if no proxy configured
• works fine if proxy configured with no_proxy (except if preceded in the same sls by file.managed from remotefs)
• does not work (ie no forwarding to proxy) if proxy configured without no_proxy

(appears that the no_proxy PR/patch is working correctly).

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

If this issue is closed prematurely, please leave a comment and we will gladly reopen the issue.

[Oloremo]

@Ch3LL run on that issue on 2019.2.2.
It's a very weird issue as a @campbellmc described and it needs to be fixed.

This configuration is more than enough to verify this issue:

test_http_source:
  file.managed:
    - name: /tmp/test.txt
    - source: https://sentry.io
    - skip_verify: True

get_agent_info:
  module.run:
    - consul.agent_self:
      - consul_url: http://127.0.0.1:8500

With proxy set in minion configs

[Oloremo]

Additionally I see this in logs when it happens:

Exception ignored in: <bound method HTTPClient.__del__ of <tornado.httpclient.HTTPClient object at 0x7f8c6ae912b0>>
Traceback (most recent call last):
  File "/opt/behavox/.local/lib/python3.6/site-packages/tornado/httpclient.py", line 82, in __del__
    self.close()
  File "/opt/behavox/.local/lib/python3.6/site-packages/tornado/httpclient.py", line 86, in close
    if not self._closed:
AttributeError: 'HTTPClient' object has no attribute '_closed'

And this:

2019-10-31 00:38:18,500 [salt.log.setup] [ERROR] [JID: 20191031003810660651] An un-handled exception was caught by salt's global exception handler:
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xa8 in position 0: invalid start byte
Traceback (most recent call last):
  File "/opt/behavox/.local/lib/python3.6/site-packages/tornado/curl_httpclient.py", line 496, in _curl_debug
    debug_msg = native_str(debug_msg)
  File "/opt/behavox/.local/lib/python3.6/site-packages/tornado/escape.py", line 218, in to_unicode
    return value.decode("utf-8")
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xa8 in position 0: invalid start byte

And if I debug the value of the:

supports_max_body_size = 'max_body_size' in client_argspec.args

from the salt/utils/http.py
It's False for file.managed and True for consul.get request.

[Oloremo]

Salt Version:
           Salt: 2019.2.2

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: Not Installed
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.10.3
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.6.2
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 3.6.8 (default, Aug  7 2019, 17:28:10)
   python-gnupg: 0.4.5
         PyYAML: 3.11
          PyZMQ: 18.0.2
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.5.3
            ZMQ: 4.3.1

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

[Oloremo]

Seems like we're hitting this bug: https://github.com/tornadoweb/tornado/pull/2275
But the question is still - what the hell is returned from consul so it can't be decoded?

[Oloremo]

Or maybe the patch above is irrelevant.

So the problems are happening when the context is switching from proxy connection to non-proxy connection.

utils/http.py

        if proxy_host and proxy_port:
            if HAS_CURL_HTTPCLIENT is False:
                ret['error'] = ('proxy_host and proxy_port has been set. This requires pycurl and tornado, '
                                'but the libraries does not seem to be installed')
                log.error(ret['error'])
                return ret

            tornado.httpclient.AsyncHTTPClient.configure('tornado.curl_httpclient.CurlAsyncHTTPClient')
            client_argspec = salt.utils.args.get_function_argspec(
                    tornado.curl_httpclient.CurlAsyncHTTPClient.initialize)
        else:
            client_argspec = salt.utils.args.get_function_argspec(
                    tornado.simple_httpclient.SimpleAsyncHTTPClient.initialize)
        supports_max_body_size = 'max_body_size' in client_argspec.args

So at first I do something like file.managed which goes outside via proxy so is uses a CurlAsyncHTTPClient and it supports_max_body_size is set to False in that case.

After that we go to consul which is uses a connection to 127.0.0.1 which is set in no_proxy arg, so we fall into else statement and use SimpleAsyncHTTPClient and supports_max_body_size is True.

Yet we get the TypeError: initialize() got an unexpected keyword argument 'max_body_size'
So I kinda assume the following:
1) It's not related to consul, it's related to proxy logic vs non-proxy logic
2) Error is triggered by a specific order. You need to run proxy connection first
3) It feels like the non-proxy connection re-use the proxy socket\connection\object but with wrong arguments this time.

and if I replace SimpleAsyncHTTPClient with CurlAsyncHTTPClient for non-proxy connection too - everything starts to work

utils/http.py

@@ -530,8 +530,9 @@
             client_argspec = salt.utils.args.get_function_argspec(
                     tornado.curl_httpclient.CurlAsyncHTTPClient.initialize)
         else:
+            tornado.httpclient.AsyncHTTPClient.configure('tornado.curl_httpclient.CurlAsyncHTTPClient')
             client_argspec = salt.utils.args.get_function_argspec(
-                    tornado.simple_httpclient.SimpleAsyncHTTPClient.initialize)
+                    tornado.curl_httpclient.CurlAsyncHTTPClient.initialize)

[campbellmc]

I think we have some non-mutable function args being used here.
If I copy the exact function SimpleAsyncHTTPClient under a new name, and use the copied function in utils/http.py (for example SimpleAsyncHTTPClientCopy in place of SimpleAsyncHTTPClient) - it also works fine.