Error 500 on pushing to share


#1

Hi there,

with a newly installed RC 4.7.2 CE I have problems pushing to a fstab mounted share.
Permission issue?

What I checked so far:

  • Changing the main storage location to a local path -> Everything works a s expected

  • Changing the storage path to the fstab mounted share and create repo via rc web interface -> works

  • Adding new files via rc web interface -> works

  • Pushing to created repo -> fails (transfer interrupted)

  • Cloning repo via web interface to share -> fails (transfer interrupted)

The share is mounted using fstab and with user/group permissions set to rhodecode user and the repo is small (5MB).

Here are some logs:
2017-05-16 10:21:20.713 INFO [vcsserver.tweens] IP: 127.0.0.1 Request to /testrepo time: 0.394s
[2017-05-16 10:21:20 +0000] [1662] [ERROR] Error handling request /stream/hg/testrepo?cmd=unbundle
Traceback (most recent call last):
File “/opt/rhodecode/store/b39z84hz3bk507na9mv6z8qwinv29lvb-python2.7-gunicorn-19.6.0/lib/python2.7/site-packages/gunicorn/workers/sync.py”, line 135, in handle
self.handle_request(listener, req, client, addr)
File “/opt/rhodecode/store/b39z84hz3bk507na9mv6z8qwinv29lvb-python2.7-gunicorn-19.6.0/lib/python2.7/site-packages/gunicorn/workers/sync.py”, line 176, in handle_request
respiter = self.wsgi(environ, resp.start_response)
File “/opt/rhodecode/store/w6kjp4h2szaa42f7yksgi3lqnpp2ax51-python2.7-pyramid-1.7.4/lib/python2.7/site-packages/pyramid/router.py”, line 236, in call
response = self.invoke_subrequest(request, use_tweens=True)
File “/opt/rhodecode/store/w6kjp4h2szaa42f7yksgi3lqnpp2ax51-python2.7-pyramid-1.7.4/lib/python2.7/site-packages/pyramid/router.py”, line 211, in invoke_subrequest
response = handle_request(request)
File “/opt/rhodecode/store/xpdg97yhawxyvrh90666414x459kriq3-python2.7-rhodecode-vcsserver-4.7.2/lib/python2.7/site-packages/vcsserver/tweens.py”, line 45, in call
response = self.handler(request)
File “/opt/rhodecode/store/w6kjp4h2szaa42f7yksgi3lqnpp2ax51-python2.7-pyramid-1.7.4/lib/python2.7/site-packages/pyramid/tweens.py”, line 51, in excview_tween
request_iface=request_iface.combined
File “/opt/rhodecode/store/w6kjp4h2szaa42f7yksgi3lqnpp2ax51-python2.7-pyramid-1.7.4/lib/python2.7/site-packages/pyramid/view.py”, line 547, in _call_view
response = view_callable(context, request)
File “/opt/rhodecode/store/w6kjp4h2szaa42f7yksgi3lqnpp2ax51-python2.7-pyramid-1.7.4/lib/python2.7/site-packages/pyramid/viewderivers.py”, line 413, in viewresult_to_response
result = view(context, request)
File “/opt/rhodecode/store/w6kjp4h2szaa42f7yksgi3lqnpp2ax51-python2.7-pyramid-1.7.4/lib/python2.7/site-packages/pyramid/viewderivers.py”, line 106, in mapped_view
return _mapped_view(context, request)
File “/opt/rhodecode/store/xpdg97yhawxyvrh90666414x459kriq3-python2.7-rhodecode-vcsserver-4.7.2/lib/python2.7/site-packages/vcsserver/http_main.py”, line 414, in handle_vcs_exception
raise exception
RepoError: abandoned transaction found
[16/May/2017:10:21:20 +0200] GNCRN <1662> 127.0.0.1 rqt:0.000676 500 - “POST:None cmd=unbundle” usr:- “-” "-"
2017-05-16 10:21:20.782 DEBUG [vcsserver.http_main] method called:localrepository with kwargs:{}
2017-05-16 10:21:20.783 DEBUG [vcsserver.base] INIT MercurialFactory@/mnt/share/RhodeCodeSCM/testrepo repo object based on wire {‘path’: ‘/mnt/share/RhodeCodeSCM/testrepo’, ‘cache’: False, ‘config’: [[‘web’, ‘push_ssl’, ‘False’], [‘web’, ‘allow_archive’, ‘gz zip bz2’], [‘web’, ‘allow_push’, ‘’], [‘web’, ‘baseurl’, ‘/’], [‘extensions’, ‘largefiles’, ‘’], [‘phases’, ‘publish’, ‘True’], [‘largefiles’, ‘usercache’, ‘/mnt/share/RhodeCodeSCM/.cache/largefiles’], [‘hooks’, ‘changegroup.repo_size’, ‘python:vcsserver.hooks.repo_size’], [‘hooks’, ‘pretxnchangegroup.pre_push’, ‘python:vcsserver.hooks.pre_push’], [‘hooks’, ‘outgoing.pull_logger’, ‘python:vcsserver.hooks.log_pull_action’], [‘hooks’, ‘changegroup.push_logger’, ‘python:vcsserver.hooks.log_push_action’], [‘hooks’, ‘preoutgoing.pre_pull’, ‘python:vcsserver.hooks.pre_pull’], [‘hooks’, ‘prechangegroup.pre_push’, ‘python:vcsserver.hooks.pre_push’], [‘vcs_svn_proxy’, ‘http_requests_enabled’, ‘False’], [‘vcs_svn_proxy’, ‘http_server_url’, ‘’], [‘vcs_svn_tag’, ‘ff89f8c714d135d865f44b90e5413b88de19a55f’, '/tags/’], [‘paths’, ‘/’, ‘/mnt/share/RhodeCodeSCM’], [‘vcs_git_lfs’, ‘store_location’, ‘/mnt/share/RhodeCodeSCM/.cache/lfs_store’], [‘vcs_svn_branch’, ‘9aac1a38c3b8a0cdc4ae0f960a5f83332bc4fa5e’, ‘/branches/’], [‘vcs_svn_branch’, ‘c7e6a611c87da06529fd0dd733308481d67c71a8’, ‘/trunk’]], ‘context’: UUID(‘aa019e6d-39da-47ae-bcd9-aebec7eadefa’)}. Context: aa019e6d-39da-47ae-bcd9-aebec7eadefa
2017-05-16 10:21:20.791 INFO [vcsserver.tweens] IP: 127.0.0.1 Request to /hg time: 0.010s
2017-05-16 10:21:20.794 DEBUG [vcsserver.http_main] method called:get_all_commit_ids with kwargs:{}
2017-05-16 10:21:20.794 DEBUG [vcsserver.base] INIT MercurialFactory@/mnt/share/RhodeCodeSCM/testrepo repo object based on wire {‘path’: ‘/mnt/share/RhodeCodeSCM/testrepo’, ‘cache’: False, ‘config’: [[‘web’, ‘push_ssl’, ‘False’], [‘web’, ‘allow_archive’, ‘gz zip bz2’], [‘web’, ‘allow_push’, '
’], [‘web’, ‘baseurl’, ‘/’], [‘extensions’, ‘largefiles’, ‘’], [‘phases’, ‘publish’, ‘True’], [‘largefiles’, ‘usercache’, ‘/mnt/share/RhodeCodeSCM/.cache/largefiles’], [‘hooks’, ‘changegroup.repo_size’, ‘python:vcsserver.hooks.repo_size’], [‘hooks’, ‘pretxnchangegroup.pre_push’, ‘python:vcsserver.hooks.pre_push’], [‘hooks’, ‘outgoing.pull_logger’, ‘python:vcsserver.hooks.log_pull_action’], [‘hooks’, ‘changegroup.push_logger’, ‘python:vcsserver.hooks.log_push_action’], [‘hooks’, ‘preoutgoing.pre_pull’, ‘python:vcsserver.hooks.pre_pull’], [‘hooks’, ‘prechangegroup.pre_push’, ‘python:vcsserver.hooks.pre_push’], [‘vcs_svn_proxy’, ‘http_requests_enabled’, ‘False’], [‘vcs_svn_proxy’, ‘http_server_url’, ‘’], [‘vcs_svn_tag’, ‘ff89f8c714d135d865f44b90e5413b88de19a55f’, ‘/tags/’], [‘paths’, ‘/’, ‘/mnt/share/RhodeCodeSCM’], [‘vcs_git_lfs’, ‘store_location’, ‘/mnt/share/RhodeCodeSCM/.cache/lfs_store’], [‘vcs_svn_branch’, ‘9aac1a38c3b8a0cdc4ae0f960a5f83332bc4fa5e’, '/branches/’], [‘vcs_svn_branch’, ‘c7e6a611c87da06529fd0dd733308481d67c71a8’, ‘/trunk’]], ‘context’: UUID(‘aa019e6d-39da-47ae-bcd9-aebec7eadefa’)}. Context: aa019e6d-39da-47ae-bcd9-aebec7eadefa
[16/May/2017:10:21:20 +0200] GNCRN <1662> 127.0.0.1 rqt:0.013715 200 51 "POST:/hg " usr:- “-” "PycURL/7.19.5 libcurl/7.50.3 OpenSSL/1.0.2h zlib/1.2.8 libssh2/1.7.0 nghttp2/1.7.1"
2017-05-16 10:21:20.803 INFO [vcsserver.tweens] IP: 127.0.0.1 Request to /hg time: 0.010s
[16/May/2017:10:21:20 +0200] GNCRN <1663> 127.0.0.1 rqt:0.012919 200 51 "POST:/hg " usr:- “-” “PycURL/7.19.5 libcurl/7.50.3 OpenSSL/1.0.2h zlib/1.2.8 libssh2/1.7.0 nghttp2/1.7.1”


#2

Looks like permissions issue, is there anything in vcsserver.log ?

Also might be that the fstab is very slow ? did you try to do a local hg clone from the host OS and fstab mounted share ?


#3

Hi Marcin,

it indeed was a false configured share (permission). Nevertheless I am now facing a error 502 (behind apache).
vcsserver log

apache error log:

[Tue May 16 14:34:44.183833 2017] [proxy_http:error] [pid 947:tid 140527781480192] (20014)Internal error: [client 192.168.101.124:53007] AH01102: error reading status line from remote server 127.0.0.1:10002
[Tue May 16 14:34:45.415674 2017] [proxy_http:error] [pid 945:tid 140527848621824] (20014)Internal error: [client 192.168.101.124:53008] AH01102: error reading status line from remote server 127.0.0.1:10002
[Tue May 16 14:34:45.415719 2017] [proxy:error] [pid 945:tid 140527848621824] [client 192.168.101.124:53008] AH00898: Error reading from remote server returned by /testrepo
[Tue May 16 14:39:00.676748 2017] [proxy_http:error] [pid 947:tid 140527806658304] (20014)Internal error: [client 192.168.101.124:53021] AH01102: error reading status line from remote server 127.0.0.1:10002
[Tue May 16 14:39:01.717925 2017] [proxy_http:error] [pid 945:tid 140527798265600] (20014)Internal error: [client 192.168.101.124:53022] AH01102: error reading status line from remote server 127.0.0.1:10002
[Tue May 16 14:39:01.717958 2017] [proxy:error] [pid 945:tid 140527798265600] [client 192.168.101.124:53022] AH00898: Error reading from remote server returned by /testrepo
[Tue May 16 14:51:41.284896 2017] [proxy_http:error] [pid 947:tid 140527747909376] (20014)Internal error: [client 192.168.101.124:53075] AH01102: error reading status line from remote server 127.0.0.1:10002
[Tue May 16 14:51:42.422154 2017] [proxy_http:error] [pid 945:tid 140527773087488] (20014)Internal error: [client 192.168.101.124:53076] AH01102: error reading status line from remote server 127.0.0.1:10002
[Tue May 16 14:51:42.422196 2017] [proxy:error] [pid 945:tid 140527773087488] [client 192.168.101.124:53076] AH00898: Error reading from remote server returned by /testrepo
[Tue May 16 14:52:03.675125 2017] [proxy_http:error] [pid 945:tid 140527815051008] (20014)Internal error: [client 192.168.101.124:53078] AH01102: error reading status line from remote server 127.0.0.1:10002
[Tue May 16 14:52:04.808721 2017] [proxy_http:error] [pid 947:tid 140527882192640] (20014)Internal error: [client 192.168.101.124:53079] AH01102: error reading status line from remote server 127.0.0.1:10002
[Tue May 16 14:52:04.808763 2017] [proxy:error] [pid 947:tid 140527882192640] [client 192.168.101.124:53079] AH00898: Error reading from remote server returned by /testrepo


#4

With the 500 “solved” the 502 persists. See logs above.

What I’ve tested now:

  • Creating repo on fstab share via web interface -> works
  • Pushing to repo on fstab share -> 502
  • Pushing to repo on local path -> works
  • Local hg clone from RC host OS and fstab share -> works

#5

Hmm, imho the 502 should be reported somewhere in rhodecode or vcsserver log, didn’t ou find nothing ?

502 error is mostly in cases a rhodecode worker serving process dies or kills the connection to HTTP server, such as apache. But this should be reported somewhere in the logs imho. Maybe there’s a problem with creating new files via the user who runs rhodecode service ?

Best,


#6

Never mind, was a samba related rights problem. You were right in the first place.