AuthTimeoutError with PAM-enabled su

[GoogleCodeExporter]

Hi, I'm trying an ebuild for neatx on Gentoo, and met this problem (close
to issue #14, but with current SVN, and only occurs with PAM)

What steps will reproduce the problem?
1. Install neatx r41
2. Try to login with official nxclient 3.3.0.6
3. Watch debug log

What is the expected output? What do you see instead?
neatx should see the successfull su command and go on, instead it timeouts
(see log below).

What version of the product are you using? On what operating system?
System: Gentoo ~x86 system, with PAM enabled (by default as in most systems)
shadow (for su): 4.1.4.2
neatx revision: SVN r41
NX: 3.3.0
client: 3.3.0.6

Please provide any additional information below.
With the same setup, and disabling pam in shadow, connection is successfull.

Here is the debug log:
Aug 27 15:07:47 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'NX> 105 '
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:227 <<<
'hello NXCLIENT - Version 3.3.0\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'Hello nxclient - version 3.3.0\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG nxserver_login:111
Got client protocol version 3030000 ('3.3.0'), want 3030000
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'NX> 134 Accepted protocol: 3.3.0\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'NX> 105 '
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:227 <<<
'SET SHELL_MODE SHELL\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'Set SHELL_MODE: SHELL\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'NX> 105 '
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:227 <<<
'SET AUTH_MODE PASSWORD\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'Set AUTH_MODE: PASSWORD\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'NX> 105 '
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:227 <<<
'login\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'Login\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'NX> 101 User: '
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:227 <<<
'bernard\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>> '\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'NX> 102 Password: '
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:225 <<<
[hidden]
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'**********\n'
Aug 27 15:07:48 enterprise nxserver-login[17424]: INFO nxserver_login:249
Trying login for user 'bernard' using auth method 'su'
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG auth:50
Authenticating as 'bernard', running ['/usr/lib64/neatx/nxserver',
'--proto=3030000', '--', 'bernard']
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG auth:53 Auth
command ['/usr/lib64/neatx/ttysetup', '/bin/su', 'bernard', '-c', 'cd &&
/usr/lib64/neatx/nxserver --proto=3030000 -- bernard']
Aug 27 15:07:48 enterprise su[17426]: Successful su for bernard by nx
Aug 27 15:07:48 enterprise su[17426]: + /dev/pts/0 nx:bernard
Aug 27 15:07:48 enterprise su[17426]: pam_unix(su:session): session opened
for user bernard by (uid=110)
Aug 27 15:08:18 enterprise nxserver-login[17424]: DEBUG auth:109
Authentication timed out (output='Password: ')
Aug 27 15:08:18 enterprise nxserver-login[17424]: ERROR nxserver_login:264
Error in authentication
Aug 27 15:08:18 enterprise nxserver-login[17424]: Traceback (most recent
call last):
Aug 27 15:08:18 enterprise nxserver-login[17424]:   File
"/usr/lib64/python2.6/site-packages/neatx/app/nxserver_login.py", line 259,
in _TryLogin
Aug 27 15:08:18 enterprise nxserver-login[17424]:    
authenticator.AuthenticateAndRun(username, password, args)
Aug 27 15:08:18 enterprise nxserver-login[17424]:   File
"/usr/lib64/python2.6/site-packages/neatx/auth.py", line 110, in
AuthenticateAndRun
Aug 27 15:08:18 enterprise nxserver-login[17424]:     raise
errors.AuthTimeoutError()
Aug 27 15:08:18 enterprise nxserver-login[17424]: AuthTimeoutError
Aug 27 15:08:18 enterprise nxserver-login[17424]: DEBUG protocol:172 >>>
'NX> 503 ERROR: Internal error.\n'
Aug 27 15:08:18 enterprise sshd[17415]: pam_unix(sshd:session): session
closed for user nx

neatx.conf:
loglevel = debug
nx-protocol-version = 3.3.0
netcat-path = /usr/bin/netcat
xserssion-path = /etc/X11/Sessions/Xsession

Let me know if any pam files or other configuration files may be useful

Original issue reported on code.google.com by bcafa...@gmail.com on 27 Aug 2009 at 2:18

[GoogleCodeExporter]

Ok, as far as i can tell, here's what's happening:

Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG auth:50
Authenticating as 'bernard', running ['/usr/lib64/neatx/nxserver',
'--proto=3030000', '--', 'bernard']
Aug 27 15:07:48 enterprise nxserver-login[17424]: DEBUG auth:53 Auth
command ['/usr/lib64/neatx/ttysetup', '/bin/su', 'bernard', '-c', 'cd &&
/usr/lib64/neatx/nxserver --proto=3030000 -- bernard']
Aug 27 15:07:48 enterprise su[17426]: Successful su for bernard by nx
Aug 27 15:07:48 enterprise su[17426]: + /dev/pts/0 nx:bernard
Aug 27 15:07:48 enterprise su[17426]: pam_unix(su:session): session opened
for user bernard by (uid=110)
Aug 27 15:08:18 enterprise nxserver-login[17424]: DEBUG auth:109
Authentication timed out (output='Password: ')

su is being run, and it's immediately succeeding, without prompting for a 
password.
I'm guessing your pam setup is configured to allow this. I think the fix is to 
change
lib/auth.py so that this is allowed for.

Original comment by kormat on 30 Aug 2009 at 1:25

• Changed state: Accepted

[GoogleCodeExporter]

Sorry, i'm wrong. su is outputing a password prompt (as the 'Authentication 
timed
out' log entry shows). And su is succeeding (as the su log entries show). 
However the
nxserver command isn't getting run. Can you tell me what happens if you run 
this by
hand, as the nx user:

/bin/su bernard -c 'cd && /usr/lib64/neatx/nxserver --proto=3030000 -- bernard'

Thanks,
Steve

Original comment by kormat on 30 Aug 2009 at 1:32

[GoogleCodeExporter]

Manually running it is ok:

enterprise ~ # su - nx -s /bin/bash
nx@enterprise ~ $ /bin/su bernard -c 'cd && /usr/lib64/neatx/nxserver 
--proto=3030000
-- bernard'
Password: 
NX> 103 Welcome to: enterprise.cafarelli.fr user: bernard
NX> 105 

And the corresponding log:
Aug 30 20:21:42 enterprise su[9791]: Successful su for nx by root
Aug 30 20:21:42 enterprise su[9791]: + /dev/pts/4 root:nx
Aug 30 20:21:42 enterprise su[9791]: pam_unix(su:session): session opened for 
user nx
by bernard(uid=0)
Aug 30 20:21:46 enterprise su[9820]: Successful su for bernard by nx
Aug 30 20:21:46 enterprise su[9820]: + /dev/pts/4 nx:bernard
Aug 30 20:21:46 enterprise su[9820]: pam_unix(su:session): session opened for 
user
bernard by bernard(uid=110)
Aug 30 20:22:07 enterprise nxserver[9822]: INFO nxserver:689 Starting nxserver 
for
user bernard
Aug 30 20:22:07 enterprise nxserver[9822]: DEBUG protocol:172 >>> 'NX> 103 
Welcome
to: enterprise.cafarelli.fr user: bernard\n'
Aug 30 20:22:07 enterprise nxserver[9822]: DEBUG protocol:172 >>> 'NX> 105 '

I've tried setting /bin/sh as login shell, run ssh nx@enterprise and nxserver, 
same
behaviour

Original comment by bcafa...@gmail.com on 30 Aug 2009 at 6:50

[GoogleCodeExporter]

Hmm. There seems to be quite a long pause between su suceeding, and nxserver 
being run: 

Aug 30 20:21:46 enterprise su[9820]: pam_unix(su:session): session opened for 
user
bernard by bernard(uid=110)
Aug 30 20:22:07 enterprise nxserver[9822]: INFO nxserver:689 Starting nxserver 
for
user bernard

It's possible that nxserver-login's timeout is too short. If you try increasing 
it
from 30 to 60 on this line:
http://code.google.com/p/neatx/source/browse/trunk/neatx/lib/auth.py#71 , that 
might
fix things. Let me know.

Original comment by kormat on 8 Sep 2009 at 5:40

[GoogleCodeExporter]

Thanks to your comment, I have solved this one! Commenting on the long delay 
between
su and nxserver, I saw nxssh was waiting (and timeouting) on getting xauth 
lock...

The bug was in the ebuild, which installs ~nx owned by root:root, thus 
preventing nx
user from creating .Xauthority (not sure how disabling PAM helped for this one, 
but
oh well...)

Now it works, and the authentication/login part is as fast as nx free edition at
least :) Thanks a lot for your help!

Original comment by bcafa...@gmail.com on 8 Sep 2009 at 10:15

[GoogleCodeExporter]

Great, glad to hear it's solved.

Original comment by kormat on 14 Sep 2009 at 5:18

• Changed state: Fixed