Push only working when server is on heavy load

Issue #41 resolved
Ton Plomp created an issue

I have setup RhodeCode (and hg-app) on an Ubuntu box using Apache as the primary web-server.

I can clone and use the webinterface without issues. However pushing is not working I get the following response:

But if I put my server under heavy load (like using Wireshark to trace this issue or running apt-get for a lot of packages) I can push. Somehow there is some race condition between apache and hg-app that is not triggered when the computer is slow.

Any ideas?

If I look up the apache logs I see the following entries: 192.168.1.24 - - [16/Oct/2010:14:07:55 +0200] "GET /mercurial?pairs=0000000000000000000000000000000000000000-0000000000000000000000000000000000000000&cmd=between HTTP/1.1" 401 506 "-" "mercurial/proto-1.0" 192.168.1.24 - - [16/Oct/2010:14:07:55 +0200] "GET /mercurial?pairs=0000000000000000000000000000000000000000-0000000000000000000000000000000000000000&cmd=between HTTP/1.1" 200 178 "-" "mercurial/proto-1.0" 192.168.1.24 - - [16/Oct/2010:14:07:55 +0200] "GET /mercurial?cmd=capabilities HTTP/1.1" 401 506 "-" "mercurial/proto-1.0" 192.168.1.24 - - [16/Oct/2010:14:07:55 +0200] "GET /mercurial?cmd=capabilities HTTP/1.1" 200 263 "-" "mercurial/proto-1.0" 192.168.1.24 - - [16/Oct/2010:14:07:55 +0200] "GET /mercurial?cmd=heads HTTP/1.1" 401 506 "-" "mercurial/proto-1.0" 192.168.1.24 - - [16/Oct/2010:14:07:55 +0200] "GET /mercurial?cmd=heads HTTP/1.1" 200 219 "-" "mercurial/proto-1.0" 192.168.1.24 - - [16/Oct/2010:14:07:55 +0200] "GET /mercurial?cmd=branchmap HTTP/1.1" 401 506 "-" "mercurial/proto-1.0" 192.168.1.24 - - [16/Oct/2010:14:07:55 +0200] "GET /mercurial?cmd=branchmap HTTP/1.1" 200 226 "-" "mercurial/proto-1.0" 192.168.1.24 - - [16/Oct/2010:14:07:56 +0200] "POST /mercurial?cmd=unbundle&heads=f4b8ddc3e9a0001d0589960a6fb5211dcc8edce5 HTTP/1.1" 502 444 "-" "mercurial/proto-1.0"

The log from the pylons app is not even mentioning this push: 2010-10-16 14:07:55.969 INFO [rhodecode.lib.auth] user ton authenticated correctly 2010-10-16 14:07:55.976 DEBUG [rhodecode.lib.utils] settings ui from db[hooks]changegroup.repo_size:python:rhodecode.lib.hooks.repo_size 2010-10-16 14:07:55.977 DEBUG [rhodecode.lib.utils] settings ui from db[web]push_ssl:false 2010-10-16 14:07:55.978 DEBUG [rhodecode.lib.utils] settings ui from db[web]allow_archive:gz zip bz2 2010-10-16 14:07:55.978 DEBUG [rhodecode.lib.utils] settings ui from db[web]allow_push: 2010-10-16 14:07:55.979 DEBUG [rhodecode.lib.utils] settings ui from db[web]baseurl:/ 2010-10-16 14:07:55.979 DEBUG [rhodecode.lib.utils] settings ui from db[paths]/:/home/ton/mercurial/MC2/ 2010-10-16 14:07:55.992 WARNI [rhodecode.lib.utils] Unable to read config file /home/ton/mercurial/MC2/mercurial/.hg/hgrc

Comments (25)

  1. Marcin Kuzminski repo owner

    Hmm that's a crazy error I must say.

    Try the following:

    run rhodecode on ip 0.0.0.0 (configured in the .ini file) then You can push to Your machine IP:PORT and bypass apache. See if the same problem occurs.

    Also Try running run hgserve You can run hg serve -p and specify the same port as rhodecode and try pushing using apache again.

    let me know sounds like an interesting problem.

  2. Ton Plomp reporter

    When I run Rhodecode on 0.0.0.0:5000, I cannot push either, so it looks like something in Rhodecode. When I push I get the following response:

    ----------------------------------------------------------------------------

    http authorization required

    realm: RhodeCode authentication

    user: ton

    password:

    pushing to http://192.168.1.6:5000/mercurial

    searching for changes

    abort: error: De externe host heeft een verbinding verbroken

    ----------------------------------------------------------------------------

    The last message translates 'The external host has closed the connection'

    If I look in the pylons log (started with: paster serve --log-file=/var/log/apache2/hg-appPylons.log production.ini), I get the following response: -----------------------------------------------------------------------------------

    2010-10-20 10:40:50.963 DEBUG [rhodecode.lib.utils] settings ui from db[hooks]changegroup.repo_size:python:rhodecode.lib.hooks.repo_size 2010-10-20 10:40:50.964 DEBUG [rhodecode.lib.utils] settings ui from db[web]push_ssl:false 2010-10-20 10:40:50.964 DEBUG [rhodecode.lib.utils] settings ui from db[web]allow_archive:gz zip bz2 2010-10-20 10:40:50.965 DEBUG [rhodecode.lib.utils] settings ui from db[web]allow_push:* 2010-10-20 10:40:50.965 DEBUG [rhodecode.lib.utils] settings ui from db[web]baseurl:/ 2010-10-20 10:40:50.966 DEBUG [rhodecode.lib.utils] settings ui from db[paths]/:/home/ton/mercurial/MC2/* 2010-10-20 10:40:50.977 WARNI [rhodecode.lib.utils] Unable to read config file /home/ton/mercurial/MC2/mercurial/.hg/hgrc -----------------------------------------------------------

    No mention of a push.

    I have attached my production.ini could it be something in my python setup? The logs show some unicode characters.

    Ton

  3. Marcin Kuzminski repo owner

    Before I'll get to serious debugging. Please download latest tip of rhodecode, i found a small bug in hg middleware recently If this doesn't fix it. pls try setting.

    ##option to use threads of process
    use_threadpool = false
    

    ps. don't mind the extra chars those are from coloring logs.

  4. Marcin Kuzminski repo owner

    One more thing try to set all loggers to DEBUG in the ini file to some more logs. This might help to seek the problem.

  5. Ton Plomp reporter

    Both tricks (latest tip and threadpool=false) don't help, and I have enabled all the debug levels.

    This resulted in the accompanied file, but I don't really find an issue.

    I added a .hgrc for the repository I try to push to, with a [baseurl] setting but that doesn't help either.

  6. Marcin Kuzminski repo owner

    Did You try running `hg serve` and pushing into raw hg server ? And also please run hg push --debug,

    I'll try to setup a new enviroment that's bare enough to not generate any load and try to debug this. But I'm using rhodeCode on 3 different machines making 10-15 pushes a day and never had this. But let's try with a fresh setup.

  7. Ton Plomp reporter

    There's something I totally don't understand.

    it works.

    out of the blue.

    I'll have to restart my server before I am satisfied. For future reference these logs might be usefull.

  8. Marcin Kuzminski repo owner

    So I Understand it suddenly started to work ? I'm afraid if this is a real issue it might come back. I have one more idea what might be wrong, for 1.1 I'm planning to rewrite litte db session manaegment, since now it's not so well optimized.

    If This will come back pls let me know.

    Thank You

  9. Ton Plomp reporter

    One thing I figured changed, I ran an update of my Ubuntu setup with the following updated packages: I can imagine any of the python packages is involved.

    • 37 upgrade linux-image-2.6.35-22-generic 2.6.35-22.34 2.6.35-22.35
    • desktop-file-utils 0.16-0ubuntu4
    • gconf2 2.31.91-0ubuntu3.1
    • gconf2-common 2.31.91-0ubuntu3.1
    • gdm-guest-session 0.17
    • gnome-settings-daemon 2.32.0-0ubuntu3
    • hicolor-icon-theme 0.11-1
    • initramfs-tools 0.98.1ubuntu6
    • jockey-common 0.5.10-0ubuntu5.1
    • jockey-common 0.5.10-0ubuntu5.1
    • jockey-gtk 0.5.10-0ubuntu5.1
    • libc-bin 2.12.1-0ubuntu7
    • libc-bin 2.12.1-0ubuntu7
    • libc-bin 2.12.1-0ubuntu7
    • libc-dev-bin 2.12.1-0ubuntu7
    • libc6 2.12.1-0ubuntu7
    • libc6-dev 2.12.1-0ubuntu7
    • libgconf2-4 2.31.91-0ubuntu3.1
    • libgpod-common 0.7.95-1
    • libgpod4 0.7.95-1
    • libgudev-1.0-0 1:162-2.1
    • libpoppler-glib5 0.14.3-0ubuntu1.1
    • libpoppler7 0.14.3-0ubuntu1.1
    • libudev0 162-2.1
    • libutouch-grail1 1.0.15-0ubuntu1
    • libvte-common 1:0.26.0-0ubuntu2
    • libvte9 1:0.26.0-0ubuntu2
    • libwebkit-1.0-2 1.2.5-0ubuntu0.10.10.1
    • libwebkit-1.0-common 1.2.5-0ubuntu0.10.10.1
    • linux-headers-2.6.35-22 2.6.35-22.35
    • linux-headers-2.6.35-22-generic 2.6.35-22.35
    • linux-image-2.6.35-22-generic 2.6.35-22.35
    • linux-image-2.6.35-22-generic-pae 2.6.35-22.35
    • linux-libc-dev 2.6.35-1022.35
    • man-db 2.5.7-4
    • man-db 2.5.7-4
    • mercurial 1.6.4-1ppa1
    • mercurial-common 1.6.4-1ppa1
    • poppler-utils 0.14.3-0ubuntu1.1
    • python-central 0.6.15ubuntu2
    • python-gmenu 2.30.4-0ubuntu1
    • python-support 1.0.9ubuntu1
    • python-support 1.0.9ubuntu1
    • python-vte 1:0.26.0-0ubuntu2
    • shared-mime-info 0.71-3
    • sun-java6-bin 6.22-0ubuntu110.10
    • sun-java6-jre 6.22-0ubuntu110.10
    • sun-java6-plugin 6.22-0ubuntu110.10
    • tzdata 2010m-0ubuntu0.10.10
    • udev 162-2.1
    • ureadahead 0.100.0-8
  10. Ton Plomp reporter
    • changed status to open

    And the issue has shown up again. I cannot figure this one...

    If you have any idea left, please help.

  11. Marcin Kuzminski repo owner

    Hi, I cannot recreate this in any environment, can You try the newest codes from beta branch, i did some changes concerning internal behavior of HG middleware serving mercurial requests.

  12. Marcin Kuzminski repo owner

    Ton, can You give me an update on this one ? Nobody else reported any similar issues like that one.

  13. Ton Plomp reporter

    Marcin,

    it's been a while since I tried, but I see more strange things on this apache machine, so that might be the issue.

    Will let you know if I start over!

    Ton

  14. Stephan Jauernick
    • changed status to open

    Hi,

    Sadly i have to reopen this bug as i am the second user experiencing this. I run the current easy_install version of RhodeCode and all its deps, without celery configured, behind an apache2 with ssl and reverse proxy on a subdir.

    I am getting: searching for changes abort: error: Connection reset by peer

    When directly running against rhodecode and: searching for changes abort: HTTP Error 502: Bad Gateway

    I enabled debugging and i got this as last output before the error from hg:

    2011-06-20 13:07:33.156 DEBUG [rhodecode.lib.auth] checking mercurial protocol permissions for user:XXXXXX repository:XXXXXX

    2011-06-20 13:07:33.156 DEBUG [rhodecode.lib.auth] permission granted

    How do i get more infos out of it?

    I use this cmd to push: hg push https://URI/hg/XXXX

    Any idea?

  15. Matt Michielsen

    I'm having a very similar issue. I'm running the latest 1.2 beta from tip. The problem only seems to happen when I push a larger changeset (>50MB or so).

    Here's example output from a push (served with apache with mod_proxy, no SSL at all): pushing to http://mmichielsen@hg.example.com/TestRepository searching for changes abort: HTTP Error 502: Bad Gateway

    When I try directly to the paste server, I get the following: pushing to http://mmichielsen@hg.example.com:5000/TestRepository searching for changes abort: error: An existing connection was forcibly closed by the remote host

    Pulling works fine, as does pushing smaller changesets. Nothing related to the push attempts that I can find goes in the log file, even with all of the loggers set to DEBUG.

  16. Matt Michielsen

    Hgweb through the same apache server (in a different VirtualHost) works as expected. It's what we were using before trying out RhodeCode.

  17. Marcin Kuzminski repo owner

    O one more thing, please make sure your client is not HG 1.9.1 i think i got this once with this version and it had few broken things in it.

  18. Marcin Kuzminski repo owner

    I was able to reproduce the issue with push aborting and that's have been fixed in 1.2.1

  19. Matt Michielsen

    (Reply via ma...@michielsen.us):

    Awesome. I can verify that this is fixed for me in 1.2.1. Thanks.

  20. Log in to comment