Concurrent logins cause 500 errors about salt-api

[whiteinge]

Are you trying to auth against PAM as the root user by any chance? That error looks familiar...

[sfdc-kho]

Not root. Just a regular unprivileged user.

[whiteinge]

Can you try auth'ing with Salt at the CLI with those same credentials and let me know what Salt outputs? Something like:

salt -a pam '*' test.ping

[whiteinge]

Edit: I suppose that may be tough to do concurrently...

[sfdc-kho]

Interesting. I tried your suggestion and it appears that eventually salt will hang on all but one process.

Here's the script:

#! /bin/bash

while true; do
    /usr/bin/expect -c 'spawn /usr/local/bin/salt -a pam --out json \* test.ping;  expect "username:" { send "<user>\r" }; expect "password:" { send "<password>\r" }; interact'
done

[whiteinge]

Great test. Thanks for that!

I'm getting mixed results trying to reproduce but I think it's specific to my setup here. I'll follow up on this as soon as I can. We definitely need to have working concurrent authentication!

[sfdc-kho]

Better stacktrace from OSX:

Traceback (most recent call last):
  File "/Users/kim.ho/git/salt/salt/auth/__init__.py", line 73, in __auth_call
    return self.auth[fstr](*fcall['args'], **fcall['kwargs'])
  File "/Users/kim.ho/git/salt/salt/auth/pam.py", line 147, in auth
    return authenticate(username, password, kwargs.get('service', 'login'))
  File "/Users/kim.ho/git/salt/salt/auth/pam.py", line 139, in authenticate
    retval = PAM_AUTHENTICATE(handle, 0)
ArgumentError: argument 1: <type 'exceptions.TypeError'>: expected PamHandle instance instead of PamHandle

My libpam info if this helps:

$ otool -L /usr/lib/libpam.dylib
/usr/lib/libpam.dylib:
    /usr/lib/libpam.2.dylib (compatibility version 3.0.0, current version 3.0.0)
    /usr/lib/libSystem.B.dylib (compatibility version 1.0.0, current version 159.0.0)

Here's the one I get from RHEL6 inside vagrant:

Traceback (most recent call last):
  File "/vagrant/salt/salt/auth/__init__.py", line 73, in __auth_call
    return self.auth[fstr](*fcall['args'], **fcall['kwargs'])
  File "/vagrant/salt/salt/auth/pam.py", line 148, in auth
    return authenticate(username, password, kwargs.get('service', 'login'))
  File "/vagrant/salt/salt/auth/pam.py", line 133, in authenticate
    retval = PAM_START(service, username, pointer(conv), pointer(handle))
ArgumentError: argument 3: <type 'exceptions.TypeError'>: expected LP_PamConv instance instead of LP_PamConv

[CRITICAL] Authentication module threw an exception: argument 3: <type 'exceptions.TypeError'>: expected LP_PamConv instance instead of LP_PamConv

[whiteinge]

Thank you for the additional details! We're all at PyCon this weekend but we'll take a closer look at this once the conference is over.

[thatch45]

We have been looking into this and have not been able to reproduce it yet. We are working on some patches to give you to try.

[sfdc-kho]

I seem to have fixed the issue that I'm seeing with this patch[1] but it's unclear to me why it fixes the issue. All I've done is force cast to the same type rather than using POINTER() to create a ctype even though they should be the same thing[2]. Hopefully, someone familiar with python/ctypes can shed some light on whether this a configuration problem with our environments.

[1]http://pastebin.com/LLnhnuxb
[2]http://docs.python.org/2/library/ctypes.html

[sfdc-kho]

In RHEL6, I'm still getting this error but it's much less frequent:

[CRITICAL] Authentication module threw an exception: incompatible types, CFunctionType instance instead of CFunctionType instance
Traceback (most recent call last):
  File "/vagrant/salt/salt/auth/__init__.py", line 73, in __auth_call
    return self.auth[fstr](*fcall['args'], **fcall['kwargs'])
  File "/vagrant/salt/salt/auth/pam.py", line 150, in auth
    return authenticate(username, password, kwargs.get('service', 'login'))
  File "/vagrant/salt/salt/auth/pam.py", line 131, in authenticate
    conv = PamConv(my_conv, 0)
TypeError: incompatible types, CFunctionType instance instead of CFunctionType instance

The RHEL6 environment is running python 2.6.6 whereas OSX is running 2.7.3

[whiteinge]

@sfdc-kho thank you for the patch! This is a bit out of my wheelhouse so I've run this past @thatch45 and he'll follow-up a bit later today.

[thatch45]

These additions look safe, but I am not sure why the concurrency is giving us this problem yet. I would say that we should add this patch and have a fallback try/except that will run a few retries until we can figure out the underlying problem.
I will open an issue on saltstack/salt to track this

[sfdc-kho]

Hey guys,

Just wanted to touch base on where we are on this. I don't suppose anyone else has had any luck reproducing this issue either through salt-api or through the salt client directly? Are we going to proceed with patching up the salt module in the interim?

[thatch45]

Sorry about the slow repsponses here, lets patch it up for now. Do you want to open a pull req?

[sfdc-kho]

Will do. I'll also work in the try/except retry logic as well.

[thatch45]

Thanks! I greatly appreciate it!

[sfdc-kho]

I've done a bit more digging into this issue and I think I've managed to create a reproducible test case. It seems to have something to do with concurrent auth module loading.

from ctypes import *
import salt.auth
import ast, traceback

if __name__ == '__main__':
    opts = ast.literal_eval("{ 'external_auth': {'pam': {'service': ['.*']}}, 'extension_modules': ''}")
    auth = salt.auth.LoadAuth(opts)

    handle = auth.auth['pam.PamHandle']()
    print "Does handle match arg type? {0}".format(type(handle) == auth.auth['pam.PAM_AUTHENTICATE'].argtypes[0])

    salt.auth.LoadAuth(opts)
    print "Does handle match arg type? {0}".format(type(handle) == auth.auth['pam.PAM_AUTHENTICATE'].argtypes[0])
    try:
        auth.auth['pam.PAM_AUTHENTICATE'](handle, 0)
    except ArgumentError:
        traceback.print_exc()

    print "Now try to force cast"
    auth.auth['pam.PAM_AUTHENTICATE'](cast(addressof(handle), POINTER(auth.auth['pam.PAM_AUTHENTICATE'].argtypes[0])).contents, 0)
    print "Called PAM_AUTHENTICATE successfully"

On both our RHEL6 and OSX machines, this gives:

[vagrant@piab1-saltm1-1-piab salt-api]$ python scripts/test.py 
Does handle match arg type? True
Does handle match arg type? False
Traceback (most recent call last):
  File "scripts/test.py", line 20, in <module>
    auth.auth['pam.PAM_AUTHENTICATE'](handle, 0)
ArgumentError: argument 1: <type 'exceptions.TypeError'>: expected PamHandle instance instead of PamHandle
Now try to force cast
Called PAM_AUTHENTICATE successfully

If loading is in fact the root cause of the issue, the most straight-forward fix would be stop reloading auth in /login. We could also remove the hack in auth/pam. Thoughts? I've tried a patch locally and it seems to be harmless and actually seems to result in slight better login throughput (not that login performance is a huge bottleneck)

[whiteinge]

Interesting find! Aside from an apparent concurrency problem in the loader, it does make sense to load the auth module just one time anyway. Is the above commit what you had in mind?

[whiteinge]

BTW, I can reproduce the same output from running your script on both Fedora 17 and Ubuntu Lucid.

[sfdc-kho]

Yes that's exactly what I was thinking. I will submit a pull for reverting the earlier hack. Resolving this issue. I'm not sure if there's a larger loader bug here (or whether loader is simply not meant to be used like this) but will leave to you guys to make that call.

[whiteinge]

Thank you for your work tracking this down!