RhodeCode CE/EE

Client output
$ time git clone http://admin@rc-beta.pnl.gov/ARES/AVID
Cloning into 'AVID'...
error: RPC failed; result=22, HTTP code = 500
fatal: The remote end hung up unexpectedly

real 9m26.855s
user 0m0.082s
sys 0m0.249s

Enterprise-1.log output

2015-03-18 08:10:51.605 DEBUG [rhodecode.lib.middleware.vcs] request path: /ARES/AVID/info/refs detected as HG False
2015-03-18 08:10:51.605 DEBUG [rhodecode.lib.middleware.vcs] request path: /ARES/AVID/info/refs detected as GIT True
2015-03-18 08:10:51.605 DEBUG [rhodecode.lib.middleware.vcs] content not gzipped, gzipMiddleware passing request further
2015-03-18 08:10:51.641 DEBUG [rhodecode.lib.middleware.simplevcs] Extracted repo name is ARES/AVID
2015-03-18 08:10:51.642 DEBUG [rhodecode.lib.utils] Checking if repo: ARES/AVID is a valid path
2015-03-18 08:10:51.642 DEBUG [rhodecode.lib.vcs.client] RepoMaker call on /data/rhodecode/ARES/AVID
2015-03-18 08:10:51.642 DEBUG [rhodecode.lib.vcs.client] Calling @assert_correct_path
2015-03-18 08:10:51.645 DEBUG [rhodecode.lib.vcs.client] RepoMaker call on /data/rhodecode/ARES/AVID
2015-03-18 08:10:51.645 DEBUG [rhodecode.lib.vcs.client] Calling @is_path_valid_repository
2015-03-18 08:10:51.651 DEBUG [beaker.container] lock_creatfunc (didnt wait)
2015-03-18 08:10:51.651 DEBUG [beaker.container] get_value creating new value
2015-03-18 08:10:51.654 DEBUG [beaker.container] set_value stored time 1426691451.654518 expire time 10
2015-03-18 08:10:51.654 DEBUG [beaker.container] released create lock
2015-03-18 08:10:51.655 DEBUG [beaker.container] lock_creatfunc (didnt wait)
2015-03-18 08:10:51.655 DEBUG [beaker.container] get_value creating new value
2015-03-18 08:10:51.663 DEBUG [beaker.container] set_value stored time 1426691451.663413 expire time 10
2015-03-18 08:10:51.663 DEBUG [beaker.container] released create lock
2015-03-18 08:10:51.664 DEBUG [beaker.container] lock_createfunc (waiting)
2015-03-18 08:10:51.664 DEBUG [beaker.container] lock_createfunc (waited)
2015-03-18 08:10:51.664 DEBUG [beaker.container] get_value creating new value
2015-03-18 08:10:51.674 DEBUG [beaker.container] set_value stored time 1426691451.674971 expire time 10
2015-03-18 08:10:51.675 DEBUG [beaker.container] released create lock
2015-03-18 08:10:51.675 DEBUG [rhodecode.lib.auth] checking if ip:130.20.174.26 is subnet of set(['0.0.0.0/0', '::/0'])
2015-03-18 08:10:51.675 DEBUG [rhodecode.lib.auth] IP 130.20.174.26 is network 0.0.0.0/0
2015-03-18 08:10:51.676 DEBUG [rhodecode.lib.auth] IP:130.20.174.26 is in range of set(['0.0.0.0/0', '::/0'])
2015-03-18 08:10:51.676 INFO [rhodecode.lib.middleware.simplevcs] Access for IP:130.20.174.26 allowed
2015-03-18 08:10:51.676 DEBUG [rhodecode.lib.auth] No data in that could been used to log in
2015-03-18 08:10:51.677 DEBUG [rhodecode.lib.auth] Failed to load user. Fallback to default user
2015-03-18 08:10:51.677 DEBUG [rhodecode.model.user] doing fill data based on: user_id:1 api_key:None username:None
2015-03-18 08:10:51.677 DEBUG [rhodecode.model.user] filling user: data
2015-03-18 08:10:51.728 DEBUG [rhodecode.lib.auth] Auth User is now
2015-03-18 08:10:51.728 DEBUG [rhodecode.lib.auth] Checking VCS protocol permissions set(['repository.read', 'repository.admin', 'repository.write']) for user: repo:ARES/AVID
2015-03-18 08:10:51.753 DEBUG [rhodecode.lib.auth] Computing PERMISSION tree for scope {'user_group_id': -1, 'repo_id': 1, 'repo_name': u'ARES/AVID', 'repo_group_id': -1}
2015-03-18 08:10:51.837 DEBUG [rhodecode.lib.auth] PERMISSION tree computed [('repositories', 1), ('user_groups', 0), ('repositories_groups', 0), ('global', 11)]
2015-03-18 08:10:51.837 DEBUG [rhodecode.lib.auth] Permission to repo:ARES/AVID GRANTED for user: @ PermissionMiddleware
2015-03-18 08:10:51.838 DEBUG [beaker.container] lock_creatfunc (didnt wait)
2015-03-18 08:10:51.838 DEBUG [beaker.container] get_value creating new value
2015-03-18 08:10:51.840 DEBUG [beaker.container] set_value stored time 1426691451.840897 expire time 10
2015-03-18 08:10:51.841 DEBUG [beaker.container] released create lock
2015-03-18 08:10:51.841 DEBUG [rhodecode.lib.middleware.simplevcs] Repository path is /data/rhodecode/ARES/AVID
2015-03-18 08:10:51.841 INFO [rhodecode.lib.middleware.simplevcs] pull action on git repo "ARES/AVID" by "default" from 130.20.174.26
2015-03-18 08:10:51.841 DEBUG [rhodecode.lib.hooks_daemon] Preparing callback daemon and registering hook object
2015-03-18 08:10:51.843 DEBUG [rhodecode.lib.hooks_daemon] Hooks uri is: PYRO:obj_4f77b244c6a94aa5976c9870c49968e3@localhost:53401
2015-03-18 08:10:51.843 DEBUG [rhodecode.lib.hooks_daemon] Running event loop of callback daemon in background thread
2015-03-18 08:10:51.844 DEBUG [rhodecode.lib.middleware.simplevcs] HOOKS extras is {'hooks': ['push', 'pull'], 'locked_by': [None, None, None], 'git_update_server_info': False, 'config': '/root/.rccontrol/enterprise-1/rhodecode.ini', 'ip': '130.20.174.26', 'make_lock': None, 'action': 'pull', 'git_path': '/opt/rhodecode/store/3flkiihiiifnpgz0rajf65x407ij4vvi-python2.7-RhodeCodeEnterprise-3.1.0/bin/git', 'username': u'default', 'repository': 'ARES/AVID', 'hooks_uri': 'PYRO:obj_4f77b244c6a94aa5976c9870c49968e3@localhost:53401', 'server_url': 'http://rc-beta.pnl.gov', 'scm': 'git'}
2015-03-18 08:10:51.844 DEBUG [rhodecode.lib.middleware.utils.wsgi_app_caller_client] Forwarding WSGI request via proxy
[2015-03-18 08:17:09 +0000] [10955] [CRITICAL] WORKER TIMEOUT (pid:10986)
2015-03-18 08:17:09.263 DEBUG [rhodecode.lib.hooks_daemon] Waiting for background thread to finish.
2015-03-18 08:17:09.275 INFO [rhodecode.lib.middleware.wrapper] IP: 130.20.174.26 Request to /ARES/AVID/info/refs time: 3600.012s
[2015-03-18 08:17:09 +0000] [10986] [INFO] Worker exiting (pid: 10986)
Exception TypeError: TypeError('an integer is required',) in > ignored
Exception TypeError: TypeError('an integer is required',) in > ignored
[2015-03-18 08:17:09 +0000] [23186] [INFO] Booting worker with pid: 23186
2015-03-18 08:17:09.395 DEBUG [rhodecode.lib.middleware.utils.wsgi_app_caller_client] Got result from proxy, returning to WSGI container
2015-03-18 08:17:09.396 DEBUG [rhodecode.lib.hooks_daemon] Waiting for background thread to finish.
2015-03-18 08:17:09.403 INFO [rhodecode.lib.middleware.wrapper] IP: 130.20.174.26 Request to /ARES/AVID/info/refs time: 377.799s
2015-03-18 08:17:09.825 DEBUG [rhodecode.lib.middleware.vcs] request path: /ARES/AVID/git-upload-pack detected as HG False
2015-03-18 08:17:09.825 DEBUG [rhodecode.lib.middleware.vcs] request path: /ARES/AVID/git-upload-pack detected as GIT True
2015-03-18 08:17:09.826 DEBUG [rhodecode.lib.middleware.vcs] content not gzipped, gzipMiddleware passing request further
2015-03-18 08:17:09.861 DEBUG [rhodecode.lib.middleware.simplevcs] Extracted repo name is ARES/AVID
2015-03-18 08:17:09.862 DEBUG [rhodecode.lib.utils] Checking if repo: ARES/AVID is a valid path
2015-03-18 08:17:09.862 DEBUG [rhodecode.lib.vcs.client] RepoMaker call on /data/rhodecode/ARES/AVID
2015-03-18 08:17:09.862 DEBUG [rhodecode.lib.vcs.client] Calling @assert_correct_path
2015-03-18 08:17:09.865 DEBUG [rhodecode.lib.vcs.client] RepoMaker call on /data/rhodecode/ARES/AVID
2015-03-18 08:17:09.866 DEBUG [rhodecode.lib.vcs.client] Calling @is_path_valid_repository
2015-03-18 08:17:09.873 DEBUG [beaker.container] lock_creatfunc (didnt wait)
2015-03-18 08:17:09.873 DEBUG [beaker.container] get_value creating new value
2015-03-18 08:17:09.876 DEBUG [beaker.container] set_value stored time 1426691829.876274 expire time 10
2015-03-18 08:17:09.876 DEBUG [beaker.container] released create lock
2015-03-18 08:17:09.877 DEBUG [beaker.container] lock_creatfunc (didnt wait)
2015-03-18 08:17:09.877 DEBUG [beaker.container] get_value creating new value
2015-03-18 08:17:09.885 DEBUG [beaker.container] set_value stored time 1426691829.88527 expire time 10
2015-03-18 08:17:09.885 DEBUG [beaker.container] released create lock
2015-03-18 08:17:09.886 DEBUG [beaker.container] lock_creatfunc (didnt wait)
2015-03-18 08:17:09.886 DEBUG [beaker.container] get_value creating new value
2015-03-18 08:17:09.894 DEBUG [beaker.container] set_value stored time 1426691829.894015 expire time 10
2015-03-18 08:17:09.894 DEBUG [beaker.container] released create lock
2015-03-18 08:17:09.894 DEBUG [rhodecode.lib.auth] checking if ip:130.20.174.26 is subnet of set(['0.0.0.0/0', '::/0'])
2015-03-18 08:17:09.894 DEBUG [rhodecode.lib.auth] IP 130.20.174.26 is network 0.0.0.0/0
2015-03-18 08:17:09.895 DEBUG [rhodecode.lib.auth] IP:130.20.174.26 is in range of set(['0.0.0.0/0', '::/0'])
2015-03-18 08:17:09.895 INFO [rhodecode.lib.middleware.simplevcs] Access for IP:130.20.174.26 allowed
2015-03-18 08:17:09.896 DEBUG [rhodecode.lib.auth] No data in that could been used to log in
2015-03-18 08:17:09.896 DEBUG [rhodecode.lib.auth] Failed to load user. Fallback to default user
2015-03-18 08:17:09.896 DEBUG [rhodecode.model.user] doing fill data based on: user_id:1 api_key:None username:None
2015-03-18 08:17:09.896 DEBUG [rhodecode.model.user] filling user: data
2015-03-18 08:17:10.039 DEBUG [rhodecode.lib.auth] Auth User is now
2015-03-18 08:17:10.040 DEBUG [rhodecode.lib.auth] Checking VCS protocol permissions set(['repository.read', 'repository.admin', 'repository.write']) for user: repo:ARES/AVID
2015-03-18 08:17:10.064 DEBUG [rhodecode.lib.auth] Computing PERMISSION tree for scope {'user_group_id': -1, 'repo_id': 1, 'repo_name': u'ARES/AVID', 'repo_group_id': -1}
2015-03-18 08:17:10.142 DEBUG [rhodecode.lib.auth] PERMISSION tree computed [('repositories', 1), ('user_groups', 0), ('repositories_groups', 0), ('global', 11)]
2015-03-18 08:17:10.142 DEBUG [rhodecode.lib.auth] Permission to repo:ARES/AVID GRANTED for user: @ PermissionMiddleware
2015-03-18 08:17:10.143 DEBUG [beaker.container] lock_creatfunc (didnt wait)
2015-03-18 08:17:10.143 DEBUG [beaker.container] get_value creating new value
2015-03-18 08:17:10.146 DEBUG [beaker.container] set_value stored time 1426691830.146178 expire time 10
2015-03-18 08:17:10.146 DEBUG [beaker.container] released create lock
2015-03-18 08:17:10.146 DEBUG [rhodecode.lib.middleware.simplevcs] Repository path is /data/rhodecode/ARES/AVID
2015-03-18 08:17:10.146 INFO [rhodecode.lib.middleware.simplevcs] pull action on git repo "ARES/AVID" by "default" from 130.20.174.26
2015-03-18 08:17:10.147 DEBUG [rhodecode.lib.hooks_daemon] Preparing callback daemon and registering hook object
2015-03-18 08:17:10.148 DEBUG [rhodecode.lib.hooks_daemon] Hooks uri is: PYRO:obj_7893cae0439a4a6f914402911a4e80e5@localhost:41917
2015-03-18 08:17:10.148 DEBUG [rhodecode.lib.hooks_daemon] Running event loop of callback daemon in background thread
2015-03-18 08:17:10.149 DEBUG [rhodecode.lib.middleware.simplevcs] HOOKS extras is {'hooks': ['push', 'pull'], 'locked_by': [None, None, None], 'git_update_server_info': False, 'config': '/root/.rccontrol/enterprise-1/rhodecode.ini', 'ip': '130.20.174.26', 'make_lock': None, 'action': 'pull', 'git_path': '/opt/rhodecode/store/3flkiihiiifnpgz0rajf65x407ij4vvi-python2.7-RhodeCodeEnterprise-3.1.0/bin/git', 'username': u'default', 'repository': 'ARES/AVID', 'hooks_uri': 'PYRO:obj_7893cae0439a4a6f914402911a4e80e5@localhost:41917', 'server_url': 'http://rc-beta.pnl.gov', 'scm': 'git'}
2015-03-18 08:17:10.149 DEBUG [rhodecode.lib.middleware.utils.wsgi_app_caller_client] Forwarding WSGI request via proxy
2015-03-18 08:17:10.157 DEBUG [rhodecode.lib.hooks_daemon] Called pre_pull of Hooks object
2015-03-18 08:17:10.638 DEBUG [pylons.configuration] Initializing configuration, package: 'rhodecode'
2015-03-18 08:17:10.662 INFO [rhodecode.config.environment] Enabled backends: ['hg', 'git', 'svn']
2015-03-18 08:17:10.669 INFO [rhodecode.model] initializing db for sqlite:////root/.rccontrol/enterprise-1/rhodecode.db
2015-03-18 08:17:10.669 INFO [rhodecode.lib.auth] getting information about all available permissions
2015-03-18 08:17:10.789 DEBUG [beaker.container] lock_createfunc (waiting)
2015-03-18 08:17:10.789 DEBUG [beaker.container] lock_createfunc (waited)
2015-03-18 08:17:10.789 DEBUG [beaker.container] get_value creating new value
2015-03-18 08:17:10.792 DEBUG [beaker.container] set_value stored time 1426691830.792969 expire time 10
2015-03-18 08:17:10.793 DEBUG [beaker.container] released create lock
2015-03-18 08:17:10.793 DEBUG [rhodecode.lib.utils] settings ui from db: [hooks] changegroup.repo_size=python:vcsserver.hooks.repo_size
2015-03-18 08:17:10.793 DEBUG [rhodecode.lib.utils] settings ui from db: [hooks] preoutgoing.pre_pull=python:vcsserver.hooks.pre_pull
2015-03-18 08:17:10.793 DEBUG [rhodecode.lib.utils] settings ui from db: [hooks] outgoing.pull_logger=python:vcsserver.hooks.log_pull_action
2015-03-18 08:17:10.793 DEBUG [rhodecode.lib.utils] settings ui from db: [hooks] prechangegroup.pre_push=python:vcsserver.hooks.pre_push
2015-03-18 08:17:10.793 DEBUG [rhodecode.lib.utils] settings ui from db: [hooks] changegroup.push_logger=python:vcsserver.hooks.log_push_action
2015-03-18 08:17:10.793 DEBUG [rhodecode.lib.utils] settings ui from db: [extensions] largefiles=
2015-03-18 08:17:10.794 DEBUG [rhodecode.lib.utils] settings ui from db: [largefiles] usercache=/data/rhodecode/.cache/largefiles
2015-03-18 08:17:10.794 DEBUG [rhodecode.lib.utils] settings ui from db: [vcs_svn_branch] 9aac1a38c3b8a0cdc4ae0f960a5f83332bc4fa5e=/branches/*
2015-03-18 08:17:10.794 DEBUG [rhodecode.lib.utils] settings ui from db: [vcs_svn_branch] c7e6a611c87da06529fd0dd733308481d67c71a8=/trunk
2015-03-18 08:17:10.794 DEBUG [rhodecode.lib.utils] settings ui from db: [vcs_svn_tag] ff89f8c714d135d865f44b90e5413b88de19a55f=/tags/*
2015-03-18 08:17:10.794 DEBUG [rhodecode.lib.utils] settings ui from db: [web] push_ssl=false
2015-03-18 08:17:10.794 DEBUG [rhodecode.lib.utils] settings ui from db: [web] allow_archive=gz zip bz2
2015-03-18 08:17:10.794 DEBUG [rhodecode.lib.utils] settings ui from db: [web] allow_push=*
2015-03-18 08:17:10.794 DEBUG [rhodecode.lib.utils] settings ui from db: [web] baseurl=/
2015-03-18 08:17:10.794 DEBUG [rhodecode.lib.utils] settings ui from db: [paths] /=/data/rhodecode
2015-03-18 08:17:10.794 DEBUG [rhodecode.lib.utils] settings ui from db: [phases] publish=true
2015-03-18 08:17:10.795 DEBUG [beaker.container] lock_createfunc (waiting)
2015-03-18 08:17:10.795 DEBUG [beaker.container] lock_createfunc (waited)
2015-03-18 08:17:10.795 DEBUG [beaker.container] get_value creating new value
2015-03-18 08:17:10.799 DEBUG [beaker.container] set_value stored time 1426691830.799373 expire time 10
2015-03-18 08:17:10.799 DEBUG [beaker.container] released create lock
2015-03-18 08:17:10.803 INFO [rhodecode.model.scm] scanning for repositories in /data/rhodecode
2015-03-18 08:17:10.804 DEBUG [rhodecode.lib.utils] settings ui from db: [hooks] changegroup.repo_size=python:vcsserver.hooks.repo_size
2015-03-18 08:17:10.804 DEBUG [rhodecode.lib.utils] settings ui from db: [hooks] preoutgoing.pre_pull=python:vcsserver.hooks.pre_pull
2015-03-18 08:17:10.804 DEBUG [rhodecode.lib.utils] settings ui from db: [hooks] outgoing.pull_logger=python:vcsserver.hooks.log_pull_action
2015-03-18 08:17:10.804 DEBUG [rhodecode.lib.utils] settings ui from db: [hooks] prechangegroup.pre_push=python:vcsserver.hooks.pre_push
2015-03-18 08:17:10.805 DEBUG [rhodecode.lib.utils] settings ui from db: [hooks] changegroup.push_logger=python:vcsserver.hooks.log_push_action
2015-03-18 08:17:10.805 DEBUG [rhodecode.lib.utils] settings ui from db: [extensions] largefiles=
2015-03-18 08:17:10.805 DEBUG [rhodecode.lib.utils] settings ui from db: [largefiles] usercache=/data/rhodecode/.cache/largefiles
2015-03-18 08:17:10.805 DEBUG [rhodecode.lib.utils] settings ui from db: [vcs_svn_branch] 9aac1a38c3b8a0cdc4ae0f960a5f83332bc4fa5e=/branches/*
2015-03-18 08:17:10.805 DEBUG [rhodecode.lib.utils] settings ui from db: [vcs_svn_branch] c7e6a611c87da06529fd0dd733308481d67c71a8=/trunk
2015-03-18 08:17:10.805 DEBUG [rhodecode.lib.utils] settings ui from db: [vcs_svn_tag] ff89f8c714d135d865f44b90e5413b88de19a55f=/tags/*
2015-03-18 08:17:10.805 DEBUG [rhodecode.lib.utils] settings ui from db: [web] push_ssl=false
2015-03-18 08:17:10.805 DEBUG [rhodecode.lib.utils] settings ui from db: [web] allow_archive=gz zip bz2
2015-03-18 08:17:10.805 DEBUG [rhodecode.lib.utils] settings ui from db: [web] allow_push=*
2015-03-18 08:17:10.805 DEBUG [rhodecode.lib.utils] settings ui from db: [web] baseurl=/
2015-03-18 08:17:10.806 DEBUG [rhodecode.lib.utils] settings ui from db: [paths] /=/data/rhodecode
2015-03-18 08:17:10.806 DEBUG [rhodecode.lib.utils] settings ui from db: [phases] publish=true
2015-03-18 08:17:10.807 DEBUG [rhodecode.lib.utils] now scanning in /data/rhodecode location recursive:True...
2015-03-18 08:17:10.819 DEBUG [rhodecode.lib.vcs.client] RepoMaker call on /data/rhodecode/ARES
2015-03-18 08:17:10.819 DEBUG [rhodecode.lib.vcs.client] Calling @assert_correct_path
2015-03-18 08:19:19.359 DEBUG [rhodecode.lib.hooks_daemon] Called post_pull of Hooks object
2015-03-18 08:19:19.396 INFO [rhodecode.lib.utils] Logging action:pull on ARES/AVID by user: ip:130.20.174.26
2015-03-18 08:20:18.423 DEBUG [rhodecode.lib.hooks_daemon] Waiting for background thread to finish.
2015-03-18 08:20:18.431 ERROR [rhodecode.lib.middleware.simplevcs] Exception while handling request
Traceback (most recent call last):
File "/opt/rhodecode/store/3flkiihiiifnpgz0rajf65x407ij4vvi-python2.7-RhodeCodeEnterprise-3.1.0/lib/python2.7/site-packages/rhodecode/lib/middleware/simplevcs.py", line 176, in call
File "/opt/rhodecode/store/3flkiihiiifnpgz0rajf65x407ij4vvi-python2.7-RhodeCodeEnterprise-3.1.0/lib/python2.7/site-packages/rhodecode/lib/middleware/simplevcs.py", line 346, in handle_request
File "/opt/rhodecode/store/3flkiihiiifnpgz0rajf65x407ij4vvi-python2.7-RhodeCodeEnterprise-3.1.0/lib/python2.7/site-packages/rhodecode/lib/middleware/utils/wsgi_app_caller_client.py", line 63, in __call_
File "/opt/rhodecode/store/9vcwk4p43qz5qlyizrha992q2kj0g6yr-python2.7-Pyro4-4.31/lib/python2.7/site-packages/Pyro4/core.py", line 169, in call
return self.send(self.name, args, kwargs)
File "/opt/rhodecode/store/9vcwk4p43qz5qlyizrha992q2kj0g6yr-python2.7-Pyro4-4.31/lib/python2.7/site-packages/Pyro4/core.py", line 388, in _pyroInvoke
raise data
error: 'i' format requires -2147483648 <= number <= 2147483647
2015-03-18 08:20:18.433 INFO [rhodecode.lib.middleware.wrapper] IP: 130.20.174.26 Request to /ARES/AVID/git-upload-pack time: 188.608s

There's also an [2015-03-18 08:17:09 +0000] [10955] [CRITICAL] WORKER TIMEOUT (pid:10986) entry, we're trying to veirfy if this is not underlying problem.