Internal error - AuthTimeoutError about neatx HOT 15 CLOSED

Can you enable debug logging please? I'm guessing you might already have it set 
in
neatx.conf (loglevel = debug), but fedora at least doesn't log debug-level 
messages.
Adding this to syslog config file (i'm guessing /etc/syslog.conf), and 
restarting
syslog should help:

user.*  -/var/log/user.log

Thanks,
Steve

Hi Steve,

Thanks for your response.  Debugging was already enabled, the following is what 
got
logged in user.log
Jul 22 10:11:59 osl12 nxserver-login-wrapper[3094]: Started
Jul 22 10:11:59 osl12 nxserver-login[3096]: DEBUG protocol:172 >>> 'HELLO 
NXSERVER -
Version 3.3.0 - GPL\n'
Jul 22 10:11:59 osl12 nxserver-login[3096]: DEBUG protocol:172 >>> 'NX> 105 '
Jul 22 10:12:01 osl12 nxserver-login[3096]: DEBUG protocol:227 <<< 'login\n'
Jul 22 10:12:01 osl12 nxserver-login[3096]: DEBUG protocol:172 >>> 'Login\n'
Jul 22 10:12:01 osl12 nxserver-login[3096]: DEBUG protocol:172 >>> 'NX> 101 
User: '
Jul 22 10:12:03 osl12 nxserver-login[3096]: DEBUG protocol:227 <<< 'guest12\n'
Jul 22 10:12:03 osl12 nxserver-login[3096]: DEBUG protocol:172 >>> '\n'
Jul 22 10:12:03 osl12 nxserver-login[3096]: DEBUG protocol:172 >>> 'NX> 102 
Password: '
Jul 22 10:12:05 osl12 nxserver-login[3096]: DEBUG protocol:225 <<< [hidden]
Jul 22 10:12:05 osl12 nxserver-login[3096]: DEBUG protocol:172 >>> 
'**********\n'
Jul 22 10:12:05 osl12 nxserver-login[3096]: INFO nxserver_login:248 Trying 
login for
user guest12
Jul 22 10:12:05 osl12 nxserver-login[3096]: DEBUG auth:50 Authenticating as
'guest12', running ['/usr/neatx/lib/neatx/nxserver', '--proto=3030000', '--', 
'guest12']
Jul 22 10:12:05 osl12 nxserver-login[3096]: DEBUG auth:53 Auth command
['/usr/neatx/lib/neatx/ttysetup', '/bin/su', '-s', '/bin/bash', '-c', 'cd ~ &&
/usr/neatx/lib/neatx/nxserver --proto=3030000 -- guest12', 'guest12']
Jul 22 10:12:35 osl12 nxserver-login[3096]: ERROR nxserver_login:263 Error in
authentication
Jul 22 10:12:35 osl12 nxserver-login[3096]: Traceback (most recent call last):
Jul 22 10:12:35 osl12 nxserver-login[3096]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/app/nxserver_login.py", line 258, 
in
_TryLogin
Jul 22 10:12:35 osl12 nxserver-login[3096]:    
authenticator.AuthenticateAndRun(username, password, args)
Jul 22 10:12:35 osl12 nxserver-login[3096]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/auth.py", line 109, in 
AuthenticateAndRun
Jul 22 10:12:35 osl12 nxserver-login[3096]:     raise errors.AuthTimeoutError()
Jul 22 10:12:35 osl12 nxserver-login[3096]: AuthTimeoutError
Jul 22 10:12:35 osl12 nxserver-login[3096]: DEBUG protocol:172 >>> 'NX> 503 
ERROR:
Internal error.\n'
Jul 22 10:12:35 osl12 nxserver-login-wrapper[3094]: EOF on stderr, exiting

Ok great. The next thing to try is running the auth command manually:

/bin/su -s /bin/bash -c 'cd ~ && /usr/neatx/lib/neatx/nxserver --proto=3030000 
--
guest12' guest12

What you /should/ see is:

NX> 103 Welcome to: asher.home.bmop.net user: guest12

but i can only guess that something else is coming up for you.

When I run that above command directly, I get the following :

NX> 103 Welcome to: osl12.njit.edu user: guest12
NX> 105

So things seem to be working manually.  However, it is not working from the 
NXCLIENT. 

Also tried:

[root@osl12 ]# su - nx
HELLO NXSERVER - Version 3.3.0 - GPL
NX> 105 login
Login
NX> 101 User: guest12

NX> 102 Password: **********
NX> 503 ERROR: Internal error.

Anything else I should check or try ?

Thanks.

Ah, damnit, i left out the first line of my example:

Password: 
NX> 103 Welcome to: jaunty64 user: fra
NX> 105 

Can you confirm that you get a password prompt exactly like that (and nothing 
else) 
between running su and getting the nx welcome message?

I've just sent a large patch out for review to make auth more reliable, and 
with much
better logging. That should make it much much simpler to spot what's going 
wrong for you.

http://code.google.com/p/neatx/source/detail?r=31 committed, which is the above 
patch.

Thanks.  I've checked out the above patch, and this is the output from the logs 
:

Jul 27 08:31:09 osl12 nxserver-login-wrapper[17842]: Started
Jul 27 08:31:09 osl12 nxserver-login[17844]: DEBUG protocol:172 >>> 'HELLO 
NXSERVER -
Version 3.3.0 - GPL\n'
Jul 27 08:31:09 osl12 nxserver-login[17844]: DEBUG protocol:172 >>> 'NX> 105 '
Jul 27 08:31:31 osl12 nxserver-login[17844]: DEBUG protocol:227 <<< 'login\n'
Jul 27 08:31:31 osl12 nxserver-login[17844]: DEBUG protocol:172 >>> 'Login\n'
Jul 27 08:31:31 osl12 nxserver-login[17844]: DEBUG protocol:172 >>> 'NX> 101 
User: '
Jul 27 08:31:33 osl12 nxserver-login[17844]: DEBUG protocol:227 <<< 'guest12\n'
Jul 27 08:31:33 osl12 nxserver-login[17844]: DEBUG protocol:172 >>> '\n'
Jul 27 08:31:33 osl12 nxserver-login[17844]: DEBUG protocol:172 >>> 'NX> 102 
Password: '
Jul 27 08:31:36 osl12 nxserver-login[17844]: DEBUG protocol:225 <<< [hidden]
Jul 27 08:31:36 osl12 nxserver-login[17844]: DEBUG protocol:172 >>> 
'**********\n'
Jul 27 08:31:36 osl12 nxserver-login[17844]: INFO nxserver_login:249 Trying 
login for
user 'guest12' using auth method 'su'
Jul 27 08:31:36 osl12 nxserver-login[17844]: DEBUG auth:50 Authenticating as
'guest12', running ['/usr/neatx/lib/neatx/nxserver', '--proto=3030000', '--', 
'guest12']
Jul 27 08:31:36 osl12 nxserver-login[17844]: DEBUG auth:53 Auth command
['/usr/neatx/lib/neatx/ttysetup', '/bin/su', 'guest12', '-c', 'cd &&
/usr/neatx/lib/neatx/nxserver --proto=3030000 -- guest12']
Jul 27 08:32:06 osl12 nxserver-login[17844]: DEBUG auth:106 Authentication 
timed out
(output='AFS Password: ')
Jul 27 08:32:06 osl12 nxserver-login[17844]: ERROR nxserver_login:264 Error in
authentication
Jul 27 08:32:06 osl12 nxserver-login[17844]: Traceback (most recent call last):
Jul 27 08:32:06 osl12 nxserver-login[17844]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/app/nxserver_login.py", line 259, 
in
_TryLogin
Jul 27 08:32:06 osl12 nxserver-login[17844]:    
authenticator.AuthenticateAndRun(username, password, args)
Jul 27 08:32:06 osl12 nxserver-login[17844]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/auth.py", line 107, in 
AuthenticateAndRun
Jul 27 08:32:06 osl12 nxserver-login[17844]:     raise errors.AuthTimeoutError()
Jul 27 08:32:06 osl12 nxserver-login[17844]: AuthTimeoutError
Jul 27 08:32:06 osl12 nxserver-login[17844]: DEBUG protocol:172 >>> 'NX> 503 
ERROR:
Internal error.\n'
Jul 27 08:32:06 osl12 nxserver-login-wrapper[17842]: EOF on stderr, exiting

The problem appears to be that we are using the pam_afs module for 
authentication and
your authentication process was not expecting "AFS Password:" as the password 
prompt.  

Also, I see that it is using auth method su, what other types of auth methods 
are
supported ?  

Thanks.

Bingo. Ok, can you try changing this line 
http://code.google.com/p/neatx/source/browse/trunk/neatx/lib/auth.py#191 to:

return re.compile(r"^(\S+\s)?Password:\s*", re.I | re.M)

I /think/ that should fix it.

Re: auth methods, the other supported method is ssh. To use that, set 
'auth-method = 
ssh' in neatx.conf. 
http://code.google.com/p/neatx/source/browse/trunk/neatx/doc/neatx.conf.example 
shows 
the 2 other settings related to ssh auth.

Thanks, that fixed the authentication problem. The ssh authentication method 
also works.

However, now I'm getting another error when it tries to establish the session.  
The
problematic line appears to be the following:

TypeError: <ChopReader object (neatx+daemon+ChopReader) at 0x2a97167640>: 
unknown
signal name: slice-complete

Full error log below :

Jul 27 10:30:58 osl12 nxserver-login-wrapper[20286]: Started
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'HELLO 
NXSERVER -
Version 3.3.0 - GPL\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'NX> 105 '
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:227 <<< 'hello 
NXCLIENT -
Version 3.3.0\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'Hello 
nxclient -
version 3.3.0\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG nxserver_login:111 Got client
protocol version 3030000 ('3.3.0'), want 3030000
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'NX> 134 
Accepted
protocol: 3.3.0\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'NX> 105 '
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:227 <<< 'SET 
SHELL_MODE
SHELL\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'Set 
SHELL_MODE:
SHELL\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'NX> 105 '
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:227 <<< 'SET 
AUTH_MODE
PASSWORD\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'Set 
AUTH_MODE:
PASSWORD\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'NX> 105 '
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:227 <<< 'login\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'Login\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'NX> 101 
User: '
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:227 <<< 'guest12\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> '\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 'NX> 102 
Password: '
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:225 <<< [hidden]
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG protocol:172 >>> 
'**********\n'
Jul 27 10:30:58 osl12 nxserver-login[20289]: INFO nxserver_login:249 Trying 
login for
user 'guest12' using auth method 'ssh'
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG auth:50 Authenticating as
'guest12', running ['/usr/neatx/lib/neatx/nxserver', '--proto=3030000', '--', 
'guest12']
Jul 27 10:30:58 osl12 nxserver-login[20289]: DEBUG auth:53 Auth command
['/usr/neatx/lib/neatx/ttysetup', '/usr/bin/ssh', '-2', '-x', '-l', 'guest12', 
'-p',
'22', '-oNumberOfPasswordPrompts=1', '-oPreferredAuthentications=password',
'-oEscapeChar=none', '-oCompression=no', '-oStrictHostKeyChecking=no',
'-oUserKnownHostsFile=/dev/null', 'osl12.njit.edu', '--',
'/usr/neatx/lib/neatx/nxserver --proto=3030000 -- guest12']
Jul 27 10:30:58 osl12 nxserver[20298]: INFO nxserver:689 Starting nxserver for 
user
guest12
Jul 27 10:30:58 osl12 nxserver[20298]: DEBUG protocol:172 >>> 'NX> 103 Welcome 
to:
osl12.njit.edu user: guest12\n'
Jul 27 10:30:58 osl12 nxserver[20298]: DEBUG protocol:172 >>> 'NX> 105 '
Jul 27 10:30:59 osl12 nxserver[20298]: DEBUG protocol:227 <<< ' listsession
--user="guest12" --status="suspended,running" --geometry="3320x1200x24+render"
--type="unix-kde"\n'
Jul 27 10:30:59 osl12 nxserver[20298]: DEBUG protocol:172 >>> 'Listsession
--user="guest12" --status="suspended,running" --geometry="3320x1200x24+render"
--type="unix-kde"\n'
Jul 27 10:30:59 osl12 nxserver[20298]: DEBUG nxserver:315 Looking for sessions 
with
types=['unix-kde'], state=['suspended', 'running']
Jul 27 10:30:59 osl12 nxserver[20298]: DEBUG protocol:172 >>> "NX> 127 Session 
list
of user 'guest12':\n"
Jul 27 10:30:59 osl12 nxserver[20298]: DEBUG protocol:172 >>> 'Display Type     

   Session ID                       Options  Depth Screen         Status  Session Name\n'
Jul 27 10:30:59 osl12 nxserver[20298]: DEBUG protocol:172 >>> '-------
---------------- -------------------------------- -------- ----- --------------
----------- ------------------------------\n'
Jul 27 10:30:59 osl12 nxserver[20298]: DEBUG protocol:172 >>> '\n'
Jul 27 10:30:59 osl12 nxserver[20298]: DEBUG protocol:172 >>> 'NX> 148 Server
capacity: not reached for user: guest12\n'
Jul 27 10:30:59 osl12 nxserver[20298]: DEBUG protocol:172 >>> 'NX> 105 '
Jul 27 10:31:02 osl12 nxserver[20298]: DEBUG protocol:227 <<< 'startsession 
--link="lan" --backingstore="1" --encryption="1" --cache="16M" --images="64M"
--shmem="1" --shpix="1" --strict="0" --composite="1" --media="0"
--imagecompressionmethod="3" --imagecompressionlevel="-1" --render="1"
--session="osl12" --type="unix-kde" --geometry="1024x768+1148+216" 
--client="linux"
--keyboard="pc105/us" --screeninfo="1024x768x24+render"\n'
Jul 27 10:31:02 osl12 nxserver[20298]: DEBUG protocol:172 >>> 'Start session 
with:
--link="lan" --backingstore="1" --encryption="1" --cache="16M" --images="64M"
--shmem="1" --shpix="1" --strict="0" --composite="1" --media="0"
--imagecompressionmethod="3" --imagecompressionlevel="-1" --render="1"
--session="osl12" --type="unix-kde" --geometry="1024x768+1148+216" 
--client="linux"
--keyboard="pc105/us" --screeninfo="1024x768x24+render"\n'
Jul 27 10:31:02 osl12 nxserver[20298]: INFO nxserver:377 Starting new session
'277771D59C6F003CF9F596F577BB9B7C'
Jul 27 10:31:02 osl12 nxserver[20298]: DEBUG nxserver:645 Connecting to nxnode
Jul 27 10:31:02 osl12 nxserver[20298]: INFO node:514 Connecting to
'/usr/neatx/var/lib/neatx/sessions/277771D59C6F003CF9F596F577BB9B7C/nxnode.sock'
Jul 27 10:31:02 osl12 nxnode-wrapper[20322]: Started
Jul 27 10:31:02 osl12 nxnode[20324]: DEBUG nxnode:301 Starting mainloop
Jul 27 10:31:02 osl12 nxserver[20298]: DEBUG nxserver:385 Sending startsession 
command
Jul 27 10:31:02 osl12 nxserver[20298]: DEBUG node:551 Sending request: {'cmd':
'start', 'args': {'imagecompressionlevel': '-1', 'render': '1', 'composite': 
'1',
'encryption': '1', 'cache': '16M', 'geometry': '1024x768+1148+216', 'client':
'linux', 'imagecompressionmethod': '3', 'strict': '0', 'screeninfo':
'1024x768x24+render', 'session': 'osl12', 'link': 'lan', 'shmem': '1', 'media': 
'0',
'images': '64M', 'keyboard': 'pc105/us', 'type': 'unix-kde', 'shpix': '1',
'backingstore': '1'}}
Jul 27 10:31:02 osl12 nxnode[20324]: INFO nxnode:266 Connection established
Jul 27 10:31:02 osl12 nxnode-wrapper[20322]: Traceback (most recent call last):
Jul 27 10:31:02 osl12 nxnode-wrapper[20322]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/app/nxnode.py", line 259, in 
__HandleIO
Jul 27 10:31:02 osl12 nxnode-wrapper[20322]:     self.__IncomingConnection()
Jul 27 10:31:02 osl12 nxnode-wrapper[20322]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/app/nxnode.py", line 267, in
__IncomingConnection
Jul 27 10:31:02 osl12 nxnode-wrapper[20322]:    
ClientConnection(self.__ctx).Attach(conn)
Jul 27 10:31:02 osl12 nxnode-wrapper[20322]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/app/nxnode.py", line 197, in 
__init__
Jul 27 10:31:02 osl12 nxnode-wrapper[20322]:     self.__HandleSlice))
Jul 27 10:31:02 osl12 nxnode-wrapper[20322]: TypeError: <ChopReader object
(neatx+daemon+ChopReader) at 0x2a97167640>: unknown signal name: slice-complete
Jul 27 10:31:22 osl12 nxserver[20298]: ERROR protocol:165 Error while handling 
line
'startsession  --link="lan" --backingstore="1" --encryption="1" --cache="16M"
--images="64M" --shmem="1" --shpix="1" --strict="0" --composite="1" --media="0"
--imagecompressionmethod="3" --imagecompressionlevel="-1" --render="1"
--session="osl12" --type="unix-kde" --geometry="1024x768+1148+216" 
--client="linux"
--keyboard="pc105/us" --screeninfo="1024x768x24+render"'
Jul 27 10:31:22 osl12 nxserver[20298]: Traceback (most recent call last):
Jul 27 10:31:22 osl12 nxserver[20298]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/protocol.py", line 161, in 
_HandleLine
Jul 27 10:31:22 osl12 nxserver[20298]:     self._handler(line)
Jul 27 10:31:22 osl12 nxserver[20298]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/app/nxserver.py", line 203, in 
__call__
Jul 27 10:31:22 osl12 nxserver[20298]:     return self._StartSession(args)
Jul 27 10:31:22 osl12 nxserver[20298]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/app/nxserver.py", line 386, in
_StartSession
Jul 27 10:31:22 osl12 nxserver[20298]:     
nodeclient.StartSession(parsed_params)
Jul 27 10:31:22 osl12 nxserver[20298]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/node.py", line 604, in 
StartSession
Jul 27 10:31:22 osl12 nxserver[20298]:     return 
self._SendRequest(CMD_STARTSESSION,
args)
Jul 27 10:31:22 osl12 nxserver[20298]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/node.py", line 557, in 
_SendRequest
Jul 27 10:31:22 osl12 nxserver[20298]:     resp =
serializer.LoadJson(self._ReadResponse())
Jul 27 10:31:22 osl12 nxserver[20298]:   File
"/usr/neatx/lib/python2.5/site-packages/neatx/node.py", line 593, in 
_ReadResponse
Jul 27 10:31:22 osl12 nxserver[20298]:     data = self._sock.recv(4096)
Jul 27 10:31:22 osl12 nxserver[20298]: timeout: timed out
Jul 27 10:31:22 osl12 nxserver[20298]: DEBUG protocol:172 >>> 'NX> 500 Internal 
error\n'
Jul 27 10:31:22 osl12 nxserver[20298]: DEBUG protocol:172 >>> 'NX> 999 Bye.\n'
Jul 27 10:31:22 osl12 nxserver[20298]: DEBUG nxserver:701 No nxagent port, not
starting netcat
Jul 27 10:31:22 osl12 nxserver-login[20289]: DEBUG auth:130 fdcopy exited
(exitstatus=0, signum=None)
Jul 27 10:31:22 osl12 nxserver-login[20289]: INFO auth:139 Waiting for 
authenticated
program to finish
Jul 27 10:31:22 osl12 nxserver-login[20289]: DEBUG auth:149 Authenticated 
program
finished (exitstatus=0, signalstatus=None)
Jul 27 10:31:22 osl12 nxserver-login-wrapper[20286]: EOF on stderr, exiting
Jul 27 10:31:32 osl12 nxnode[20324]: ERROR nxnode:273 Session wasn't started in 
30
seconds, terminating
Jul 27 10:31:32 osl12 nxnode-wrapper[20322]: EOF on stderr, exiting

Hum. Can you tell me what version of pygoject you have installed please?

Steve

2.12.1

Ah. Apparently pygobject changed a lot between 2.12 and 2.14 (which is what 
neatx was
developed against). This is probably what's causing your issue. Is it possible 
for
you to upgrade to 2.14? I'm adding a note to INSTALL to mention the version
requirement, which we weren't aware of before.

Thanks, upgrading pygobject to 2.14 solved the problem.  Things seem to be 
working now. 

Fantastic, delighted to hear that fixed things. The patch to su auth has been
committed (http://code.google.com/p/neatx/source/detail?r=33), so i'm marking 
this as
fixed now.

Steve