classification
Title: crypt AuthenticationError introduced with new Linux kernel
Type: crash Stage: resolved
Components: Versions: Python 2.7
process
Status: closed Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: cstratak, icycle, xtreak
Priority: normal Keywords:

Created on 2019-01-14 15:52 by icycle, last changed 2019-08-30 17:45 by icycle. This issue is now closed.

Messages (5)
msg333628 - (view) Author: Brett R (icycle) Date: 2019-01-14 15:52
We are seeing a crash apparently in crypt.py when invoked via SaltStack and have narrowed it down to some change in the Linux kernel introduced by this security update: https://access.redhat.com/errata/RHSA-2018:3083

Linux kernel 3.10.0-862.14.4.el7.x86_64 works fine
Linux kernel 3.10.0-957.el7.x86_64 and later show this error:

2018-11-28T16:35:13.302740+00:00 ip-10-128-152-49 cloud-init: [INFO    ] Executing state cmd.script for [setup-secondary-ips]
2018-11-28T16:35:13.494523+00:00 ip-10-128-152-49 cloud-init: [ERROR   ] An exception occurred in this state: Traceback (most recent call last):
2018-11-28T16:35:13.497189+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/state.py", line 1889, in call
2018-11-28T16:35:13.500053+00:00 ip-10-128-152-49 cloud-init: **cdata['kwargs'])
2018-11-28T16:35:13.502780+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/loader.py", line 1839, in wrapper
2018-11-28T16:35:13.505822+00:00 ip-10-128-152-49 cloud-init: return f(*args, **kwargs)
2018-11-28T16:35:13.508537+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/states/cmd.py", line 1118, in script
2018-11-28T16:35:13.511297+00:00 ip-10-128-152-49 cloud-init: cmd_all = __salt__['cmd.script'](source, python_shell=True, **cmd_kwargs)
2018-11-28T16:35:13.514308+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/modules/cmdmod.py", line 2114, in script
2018-11-28T16:35:13.517107+00:00 ip-10-128-152-49 cloud-init: fn_ = __salt__['cp.cache_file'](source, saltenv)
2018-11-28T16:35:13.520171+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/modules/cp.py", line 474, in cache_file
2018-11-28T16:35:13.523112+00:00 ip-10-128-152-49 cloud-init: result = _client().cache_file(path, saltenv)
2018-11-28T16:35:13.526199+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/fileclient.py", line 188, in cache_file
2018-11-28T16:35:13.529055+00:00 ip-10-128-152-49 cloud-init: return self.get_url(path, '', True, saltenv, cachedir=cachedir)
2018-11-28T16:35:13.532046+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/fileclient.py", line 494, in get_url
2018-11-28T16:35:13.535280+00:00 ip-10-128-152-49 cloud-init: result = self.get_file(url, dest, makedirs, saltenv, cachedir=cachedir)
2018-11-28T16:35:13.538335+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/fileclient.py", line 1145, in get_file
2018-11-28T16:35:13.541621+00:00 ip-10-128-152-49 cloud-init: data = self.channel.send(load, raw=True)
2018-11-28T16:35:13.544750+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/utils/async.py", line 65, in wrap
2018-11-28T16:35:13.548071+00:00 ip-10-128-152-49 cloud-init: ret = self._block_future(ret)
2018-11-28T16:35:13.551304+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/utils/async.py", line 75, in _block_future
2018-11-28T16:35:13.554546+00:00 ip-10-128-152-49 cloud-init: return future.result()
2018-11-28T16:35:13.557950+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib64/python2.7/site-packages/tornado/concurrent.py", line 214, in result
2018-11-28T16:35:13.561205+00:00 ip-10-128-152-49 cloud-init: raise_exc_info(self._exc_info)
2018-11-28T16:35:13.564478+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib64/python2.7/site-packages/tornado/gen.py", line 876, in run
2018-11-28T16:35:13.568139+00:00 ip-10-128-152-49 cloud-init: yielded = self.gen.throw(*exc_info)
2018-11-28T16:35:13.571683+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/transport/zeromq.py", line 312, in send
2018-11-28T16:35:13.575103+00:00 ip-10-128-152-49 cloud-init: ret = yield self._crypted_transfer(load, tries=tries, timeout=timeout, raw=raw)
2018-11-28T16:35:13.578736+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib64/python2.7/site-packages/tornado/gen.py", line 870, in run
2018-11-28T16:35:13.582255+00:00 ip-10-128-152-49 cloud-init: value = future.result()
2018-11-28T16:35:13.585869+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib64/python2.7/site-packages/tornado/concurrent.py", line 214, in result
2018-11-28T16:35:13.589636+00:00 ip-10-128-152-49 cloud-init: raise_exc_info(self._exc_info)
2018-11-28T16:35:13.593537+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib64/python2.7/site-packages/tornado/gen.py", line 876, in run
2018-11-28T16:35:13.597250+00:00 ip-10-128-152-49 cloud-init: yielded = self.gen.throw(*exc_info)
2018-11-28T16:35:13.604695+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/transport/zeromq.py", line 284, in _crypted_transfer
2018-11-28T16:35:13.608535+00:00 ip-10-128-152-49 cloud-init: ret = yield _do_transfer()
2018-11-28T16:35:13.612022+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib64/python2.7/site-packages/tornado/gen.py", line 870, in run
2018-11-28T16:35:13.615530+00:00 ip-10-128-152-49 cloud-init: value = future.result()
2018-11-28T16:35:13.619175+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib64/python2.7/site-packages/tornado/concurrent.py", line 214, in result
2018-11-28T16:35:13.622702+00:00 ip-10-128-152-49 cloud-init: raise_exc_info(self._exc_info)
2018-11-28T16:35:13.626336+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib64/python2.7/site-packages/tornado/gen.py", line 879, in run
2018-11-28T16:35:13.629839+00:00 ip-10-128-152-49 cloud-init: yielded = self.gen.send(value)
2018-11-28T16:35:13.633372+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/transport/zeromq.py", line 271, in _do_transfer
2018-11-28T16:35:13.636931+00:00 ip-10-128-152-49 cloud-init: data = self.auth.crypticle.loads(data, raw)
2018-11-28T16:35:13.640794+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/crypt.py", line 1316, in loads
2018-11-28T16:35:13.644318+00:00 ip-10-128-152-49 cloud-init: data = self.decrypt(data)
2018-11-28T16:35:13.647997+00:00 ip-10-128-152-49 cloud-init: File "/usr/lib/python2.7/site-packages/salt/crypt.py", line 1296, in decrypt
2018-11-28T16:35:13.651578+00:00 ip-10-128-152-49 cloud-init: raise AuthenticationError('message authentication failed')
2018-11-28T16:35:13.655231+00:00 ip-10-128-152-49 cloud-init: AuthenticationError: message authentication failed
2018-11-28T16:35:13.658805+00:00 ip-10-128-152-49 cloud-init: [INFO    ] Completed state [setup-secondary-ips] at time 16:35:13.491356 duration_in_ms=196.894


This is very reproducible and we originally reported it here: https://github.com/saltstack/salt/issues/50673 but it does not appear to be related to SaltStack so I am trying this as the next place to file. 

Please advise what additional info may be needed.
msg334038 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python triager) Date: 2019-01-19 06:07
Thanks for the report. I couldn't find any CPython related stack trace in the traceback and this looks like a custom validation error raised by salt. Can you please add a simple reproducer without any external dependencies to reproduce this without which I propose to close this as third-party.

The Python version in GitHub issue report is Python 2.7.5 which is very old so can you please test this on Python 2.7.15 under different kernels as in the GitHub issue and perhaps add the traceback here for the same with a pure python reproducer without dependencies.
msg334875 - (view) Author: Brett R (icycle) Date: 2019-02-05 16:12
Karthikeyan,

Thank you for looking into this. I have been trying, in the background, to make further progress on this issue but progress is slow and other issues crop up. While the version of Python here is old, it was the latest in RHEL/CentOS 7.5. We are trying to get RHEL 7.6 running as well.

I understand that it appears 3rd party related, but I can't get much attention from the SaltStack folks either.

Appreciate your patience as I try to narrow this down further.
msg334893 - (view) Author: Charalampos Stratakis (cstratak) * Date: 2019-02-05 23:35
Hi Brett,

Those issues should be reported on Red Hat's bugzilla, if it's definite that the kernel version (or a new cpython release downstream) is the one to blame for it.

Also RHEL 7's python version while being 2.7.5, carries many additional patches on top with various fixes from later versions, so it wouldn't be easy to bisect an issue by relying solely on the upstream sources.

However it really does seem like a saltstack issue. An easier reproducer would be of great help here. As suggested before you should also try if possible, to make saltstack utilize the latest compiled python2 sources from github.
msg350886 - (view) Author: Brett R (icycle) Date: 2019-08-30 17:45
I'm marking this closed. We're past the issue, and won't be providing any more details or chasing this further. Feel free to reopen if others want to push it. Thanks for the tips.
History
Date User Action Args
2019-08-30 17:45:07icyclesetstatus: open -> closed

messages: + msg350886
stage: resolved
2019-02-05 23:35:59cstrataksetnosy: + cstratak
messages: + msg334893
2019-02-05 16:12:15icyclesetmessages: + msg334875
2019-01-19 06:07:31xtreaksetnosy: + xtreak
messages: + msg334038
2019-01-14 15:52:24icyclecreate