Closed GoogleCodeExporter closed 8 years ago
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
Original comment by kormat
on 22 Jul 2009 at 4:57
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
Original comment by andymal...@gmail.com
on 22 Jul 2009 at 5:56
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.
Original comment by kormat
on 22 Jul 2009 at 6:48
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.
Original comment by andymal...@gmail.com
on 23 Jul 2009 at 5:49
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?
Original comment by kormat
on 23 Jul 2009 at 7:07
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.
Original comment by kormat
on 24 Jul 2009 at 6:55
http://code.google.com/p/neatx/source/detail?r=31 committed, which is the above
patch.
Original comment by kormat
on 27 Jul 2009 at 9:30
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.
Original comment by andymal...@gmail.com
on 27 Jul 2009 at 1:34
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.
Original comment by kormat
on 27 Jul 2009 at 1:42
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
Original comment by andymal...@gmail.com
on 27 Jul 2009 at 2:34
Hum. Can you tell me what version of pygoject you have installed please?
Steve
Original comment by kormat
on 28 Jul 2009 at 6:12
2.12.1
Original comment by andymal...@gmail.com
on 28 Jul 2009 at 6:36
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.
Original comment by kormat
on 29 Jul 2009 at 5:48
Thanks, upgrading pygobject to 2.14 solved the problem. Things seem to be
working now.
Original comment by andymal...@gmail.com
on 29 Jul 2009 at 9:13
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
Original comment by kormat
on 30 Jul 2009 at 6:59
Original issue reported on code.google.com by
andymal...@gmail.com
on 22 Jul 2009 at 2:07