2898: ssh+svn access no more possible in version 1.7.5

andreasf********@gmai***** (Google Code) (Is this you? Claim this profile.)
Aug. 7, 2013
What version are you running?
1.7.5


What's the URL of the page containing the problem?
n.a.

What steps will reproduce the problem?
1.Running version 1.6.1
2.Subversion repository configured with ssh access. Generated key via webgui
3. Upgrade to version 1.7.5

What is the expected output? What do you see instead?
Access to the repository should be possible like before. Instead no more access to the repository is possible (no diffs can be shown any more)

What operating system are you using? What browser?
Ubuntu 12.04, Chrome

Please provide any additional information below.
#1 andreasf********@gmai***** (Google Code) (Is this you? Claim this profile.)
This is the output of the rbssh command:

Traceback (most recent call last):
  File "/usr/local/bin/rbssh", line 9, in <module>
    load_entry_point('ReviewBoard==1.7.5', 'console_scripts', 'rbssh')()
  File "/usr/local/lib/python2.7/dist-packages/ReviewBoard-1.7.5-py2.7.egg/reviewboard/cmdline/rbssh.py", line 330, in main
    channel.get_pty()
  File "/usr/local/lib/python2.7/dist-packages/paramiko-1.9.0-py2.7.egg/paramiko/channel.py", line 158, in get_pty
    self._wait_for_event()
  File "/usr/local/lib/python2.7/dist-packages/paramiko-1.9.0-py2.7.egg/paramiko/channel.py", line 1114, in _wait_for_event
    raise e
paramiko.SSHException: Channel closed.
#2 raja****@gmai***** (Google Code) (Is this you? Claim this profile.)
Looks very similar to Christian's blog post at
http://blog.chipx86.com/2013/01/26/weird-bugs-django-timezones-and-importing-from-eggs/. The Channel closed seems to indicate an abrupt closure of the connection from one of the endpoints.

Can you try and see if the timezones are the same on the server.
#3 andreasf********@gmai***** (Google Code) (Is this you? Claim this profile.)
Timezones on server and client are both CET. So this seems not to be the problem...
chipx86
#4 chipx86
In your exception that you listed, are you get thing this from a log file, or running rbssh directly?

If a log file, which one?

Can you modify the reviewboard.wsgi file to do:

    os.environ['DEBUG_RBSSH'] = '1'
    os.environ['RBSSH_LOG_DIR'] = '/tmp'

And then reload Apache, repeat the process, and see if you see any rbssh*.log files. Then provide one that shows a failure. We'll need that debug information.
  • +NeedInfo
#5 andreasf********@gmai***** (Google Code) (Is this you? Claim this profile.)
The Exception listed above was achieved by logging in as www-data user and calling rbssh directly.

When I do the raise the debug level like you suggested and try to add the svn repository via the web interface -this is what I get:

02-14 08:30 root               DEBUG    ['/usr/local/bin/rbssh', '[user]@[server]', 'svnserve', '-t']
02-14 08:30 root               DEBUG    PID 2654
02-14 08:30 root               DEBUG    !!! [server], [user], ['svnserve', '-t']

I do not think this helps us any further...
chipx86
#6 chipx86
There's absolutely nothing after that?

Can you look in the Apache error log and reviewboard.log and see if there's an exception anywhere?

It's possible your first exception is what's being thrown here, but I'm not sure about that. That looks to be a different code path than what you'd hit when accessing through the server.
#7 andreasf********@gmai***** (Google Code) (Is this you? Claim this profile.)
Ok, I think the apache/error.log show some more useful information:

[Thu Feb 14 08:30:00 2013] [error] /usr/local/lib/python2.7/dist-packages/Django-1.4.3-py2.7.egg/django/db/models/fields/__init__.py:761: RuntimeWarning: DateTimeField received a naive datetime (2013-02-07 00:00:00) while time zone support is active.
[Thu Feb 14 08:30:00 2013] [error]   RuntimeWarning)
[Thu Feb 14 08:30:00 2013] [error] /usr/local/lib/python2.7/dist-packages/Django-1.4.3-py2.7.egg/django/db/models/fields/__init__.py:761: RuntimeWarning: DateTimeField received a naive datetime (2013-02-15 00:00:00) while time zone support is active.
[Thu Feb 14 08:30:00 2013] [error]   RuntimeWarning)
[Thu Feb 14 08:30:00 2013] [error] /usr/local/lib/python2.7/dist-packages/Django-1.4.3-py2.7.egg/django/db/models/fields/__init__.py:761: RuntimeWarning: DateTimeField received a naive datetime (2013-01-15 00:00:00) while time zone support is active.
[Thu Feb 14 08:30:00 2013] [error]   RuntimeWarning)
[Thu Feb 14 08:30:00 2013] [error] /usr/local/lib/python2.7/dist-packages/Django-1.4.3-py2.7.egg/django/db/models/fields/__init__.py:761: RuntimeWarning: DateTimeField received a naive datetime (2012-12-16 00:00:00) while time zone support is active.
[Thu Feb 14 08:30:00 2013] [error]   RuntimeWarning)
[Thu Feb 14 08:30:00 2013] [error] /usr/local/lib/python2.7/dist-packages/Django-1.4.3-py2.7.egg/django/db/models/fields/__init__.py:761: RuntimeWarning: DateTimeField received a naive datetime (2012-11-16 00:00:00) while time zone support is active.
[Thu Feb 14 08:30:00 2013] [error]   RuntimeWarning)
[Thu Feb 14 08:30:02 2013] [error] /usr/local/lib/python2.7/dist-packages/Django-1.4.3-py2.7.egg/django/db/models/fields/__init__.py:761: RuntimeWarning: DateTimeField received a naive datetime (2013-01-15 00:00:00) while time zone support is active.
[Thu Feb 14 08:30:02 2013] [error]   RuntimeWarning)
[Thu Feb 14 08:30:02 2013] [error] /usr/local/lib/python2.7/dist-packages/Django-1.4.3-py2.7.egg/django/db/models/fields/__init__.py:761: RuntimeWarning: DateTimeField received a naive datetime (2013-02-14 00:00:00) while time zone support is active.
[Thu Feb 14 08:30:02 2013] [error]   RuntimeWarning)
Unable to import settings_local.py: No module named settings_local


The Reviewboard log:
2013-02-14 08:30:14,489 - DEBUG - SVNTool: Attempting ssh connection with host: [server], username: [user]
2013-02-14 08:30:19,535 - DEBUG - starting thread (client mode): 0x4a480dd0L
2013-02-14 08:30:19,539 - INFO - Connected (version 2.0, client OpenSSH_5.5p1)
2013-02-14 08:30:19,540 - DEBUG - kex algos:['diffie-hellman-group-exchange-sha256', 'diffie-hellman-group-exchange-sha1', 'diffie-hellman-group14-sha1', 'diffie-hellman-group1-sha1'] server key:['ssh-rsa', 'ssh-dss'] client encrypt:['aes128-ctr', 'aes192-ctr', 'aes256-ctr', 'arcfour256', 'arcfour128', 'aes128-cbc', '3des-cbc', 'blowfish-cbc', 'cast128-cbc', 'aes192-cbc', 'aes256-cbc', 'arcfour', 'rijndael-cbc@lysator.liu.se'] server encrypt:['aes128-ctr', 'aes192-ctr', 'aes256-ctr', 'arcfour256', 'arcfour128', 'aes128-cbc', '3des-cbc', 'blowfish-cbc', 'cast128-cbc', 'aes192-cbc', 'aes256-cbc', 'arcfour', 'rijndael-cbc@lysator.liu.se'] client mac:['hmac-md5', 'hmac-sha1', 'umac-64@openssh.com', 'hmac-ripemd160', 'hmac-ripemd160@openssh.com', 'hmac-sha1-96', 'hmac-md5-96'] server mac:['hmac-md5', 'hmac-sha1', 'umac-64@openssh.com', 'hmac-ripemd160', 'hmac-ripemd160@openssh.com', 'hmac-sha1-96', 'hmac-md5-96'] client compress:['none', 'zlib@openssh.com'] server compress:['none', 'zlib@openssh.com'] client lang:[''] server lang:[''] kex follows?False
2013-02-14 08:30:19,540 - DEBUG - Ciphers agreed: local=aes128-ctr, remote=aes128-ctr
2013-02-14 08:30:19,540 - DEBUG - using kex diffie-hellman-group1-sha1; server key type ssh-rsa; cipher: local aes128-ctr, remote aes128-ctr; mac: local hmac-sha1, remote hmac-sha1; compression: local none, remote none
2013-02-14 08:30:19,599 - DEBUG - Switch to new keys ...
2013-02-14 08:30:19,604 - DEBUG - Trying SSH key 0b0d5ec41cfe6b8ccf44c17d6fb8ee82
2013-02-14 08:30:19,636 - DEBUG - userauth is OK
2013-02-14 08:30:19,742 - INFO - Authentication (publickey) successful!
2013-02-14 08:30:19,743 - DEBUG - Debug msg: Forced command: svnserve -r /home/svnroot -t --tunnel-user=xxx
2013-02-14 08:30:19,744 - DEBUG - Debug msg: Port forwarding disabled.
2013-02-14 08:30:19,745 - DEBUG - Debug msg: Agent forwarding disabled.
2013-02-14 08:30:19,745 - DEBUG - Debug msg: X11 forwarding disabled.
2013-02-14 08:30:19,745 - DEBUG - Debug msg: Pty allocation disabled.
2013-02-14 08:30:19,745 - DEBUG - Debug msg: Forced command: svnserve -r /home/svnroot -t --tunnel-user=yyy
2013-02-14 08:30:19,746 - DEBUG - Debug msg: Port forwarding disabled.
2013-02-14 08:30:19,746 - DEBUG - Debug msg: Agent forwarding disabled.
2013-02-14 08:30:19,746 - DEBUG - Debug msg: X11 forwarding disabled.
2013-02-14 08:30:19,746 - DEBUG - Debug msg: Pty allocation disabled.
2013-02-14 08:30:19,747 - DEBUG - Debug msg: Forced command: svnserve -r /home/svnroot -t --tunnel-user=vvv
2013-02-14 08:30:19,747 - DEBUG - Debug msg: Port forwarding disabled.
2013-02-14 08:30:19,747 - DEBUG - Debug msg: Agent forwarding disabled.
2013-02-14 08:30:19,747 - DEBUG - Debug msg: X11 forwarding disabled.
2013-02-14 08:30:19,747 - DEBUG - Debug msg: Pty allocation disabled.
2013-02-14 08:30:19,748 - DEBUG - Debug msg: Forced command: svnserve -r /home/svnroot -t --tunnel-user=mmmm
2013-02-14 08:30:19,748 - DEBUG - Debug msg: Port forwarding disabled.
2013-02-14 08:30:19,748 - DEBUG - Debug msg: Agent forwarding disabled.
2013-02-14 08:30:19,748 - DEBUG - Debug msg: X11 forwarding disabled.
2013-02-14 08:30:19,749 - DEBUG - Debug msg: Pty allocation disabled.
2013-02-14 08:30:19,749 - DEBUG - Debug msg: Forced command: svnserve -r /home/svnroot -t --tunnel-user=ffff
2013-02-14 08:30:19,749 - DEBUG - Debug msg: Port forwarding disabled.
2013-02-14 08:30:19,749 - DEBUG - Debug msg: Agent forwarding disabled.
2013-02-14 08:30:20,220 - ERROR - SVN: Failed to get repository information for svn+ssh://[user]@[server]/directory: To better debug SSH connection problems, remove the -q option from 'ssh' in the [tunnels] section of your Subversion configuration file.
Network connection closed unexpectedly
chipx86
#8 chipx86
Okay, so the red flag is the failure to find setings_local. The Python path *should* inherit this. So a few questions about your setup:

1) Are you using mod_wsgi, mod_python, or something else?

2) What distro are you using?

3) Is SELinux turned on?
#9 andreasf********@gmai***** (Google Code) (Is this you? Claim this profile.)
1) I am using mod_wsgi
2) The current test setup is a debian wheezy 64 Bit machine, but I had the same problem on my Ubuntu 12.04

3) SELinux packages for debian are installed
chipx86
#10 chipx86
We've seen SELinux interfere with process spawning before. If it's active, try turning it off and see if the problem goes away.

If it's not that, the next step would be to add some logging near the top of main in rbssh and see what sys.path is. That should include your $sitedir/conf directory. If it does not, something is breaking with handling off PYTHONPATH.
#11 andreasf********@gmai***** (Google Code) (Is this you? Claim this profile.)
Switching off the SELinux does not solve the problem.
Indeed the PYTHONPATH does not contain the path to my site. How does the variable get set in the context of  ReviewBoard? Should this not be set during the installation process?
#13 rewil*****@thesb***** (Google Code) (Is this you? Claim this profile.)
I'm seeing nearly the exact same symptoms, with the exception that in comment 7, my error.log contains just this:

> Unable to import settings_local.py: No module named settings_local
> 
> Please see http://www.reviewboard.org/docs/manual/dev/admin/
> for help setting up Review Board.

I can confirm that SELInux is turned off, but I don't know how to do the other part of comment 9 - "add some logging near the top of main in rbssh and see what sys.path is". Any guidance?

Background:
- Ubuntu 12.04 LTS
- Upgraded from RB 1.6.11 to 1.7.5
- Discovered problem when trying to create a new repo right after upgrading. Also found that loading config page for an existing repo and just hitting "Save and continue editing" produces the same problem (where they were fine before upgrading).
- Time zone on server and in RB both set to 'America/Phoenix'.

I don't have any experience with Python, but I'm happy to try to do whatever you need.
david
#14 david
Can you look at the reviewboard.wsgi file generated by rb-site and attach it here?
#15 rewil*****@thesb***** (Google Code) (Is this you? Claim this profile.)
This issue was fixed for me in the subsequent 1.7.6 release that came out a few days after I added the above comment. The release notes (http://www.reviewboard.org/docs/releasenotes/reviewboard/1.7.6/) mention an SSH issue, although it's bug #2834 rather than this one. 2834 was not updated after the release (it's still "New" even now), so I figured this one was perhaps addressed as a related bug and similarly not updated. Sorry - I guess I should have added a comment.
david
#16 david
Glad to hear it.
  • -NeedInfo
    +Fixed