500 Error - possibly related to wild heads.
Summary
When attempting to view commits, branches, or files for the following repo, we get a 500 error:
- https://hg.iscimath.org/mforbes/forbes_group_website/-/commits/branch/default
- https://hg.iscimath.org/mforbes/forbes_group_website/-/branches
Cloning also fails.
Details
This is a self-hosted version of Heptapod running as a Docker image on AWS and the repo was imported from Bitbucket (hence, a little hard to reproduce since Bitbucket has stopped hosting!)
I suspect that the issue is due to the presence of wild heads that were in the original repo, but do not know how to delve deeper to see if this is actually the issue underneath, nor how to clone, close the wild heads, and fix the underlying repo.
Example Project
What is the current bug behavior?
The following return 500 errors (with any branch)
- https://hg.iscimath.org/mforbes/forbes_group_website/-/commits/branch/default (Any branch)
- https://hg.iscimath.org/mforbes/forbes_group_website/-/branches
- https://hg.iscimath.org/mforbes/forbes_group_website/-/blob/branch/default/README.md (Any file)
Cloning fails:
$ hg clone ssh://git@hg.iscimath.org:11022/mforbes/forbes_group_website
abort: no suitable response from remote hg!
$ hg clone https://hg.iscimath.org/mforbes/forbes_group_website
abort: HTTP Error 404: Not Found
What is the expected correct behavior?
Able to access the files, for example, as with other projects on the server:
- https://hg.iscimath.org/mforbes/super_hydro/-/commits/branch/default
- https://hg.iscimath.org/mforbes/super_hydro/-/branches
- https://hg.iscimath.org/mforbes/super_hydro/-/blob/branch/default/README.md
Able to clone:
$ hg clone ssh://git@hg.iscimath.org:11022/mforbes/super_hydro
destination directory: super_hydro
requesting all changes
adding changesets
adding manifests
adding file changes
added 213 changesets with 881 changes to 228 files
34 new obsolescence markers
new changesets e11e307ed831:cc8237504acc
updating to branch default
65 files updated, 0 files merged, 0 files removed, 0 files unresolved
$ hg clone https://hg.iscimath.org/mforbes/super_hydrodestination directory: super_hydro
requesting all changes
adding changesets
adding manifests
adding file changes
added 213 changesets with 881 changes to 228 files
34 new obsolescence markers
new changesets e11e307ed831:cc8237504acc
updating to branch default
65 files updated, 0 files merged, 0 files removed, 0 files unresolved
Relevant logs and/or screenshots
Logs reported with docker exec -it ${heptapod_id} gitlab-ctl tail
on the AWS host while attempting to load https://hg.iscimath.org/mforbes/forbes_group_website/-/commits/branch/default:
Detailed Log Reports.
==> /var/log/gitlab/gitlab-rails/production.log <==
Started GET "/mforbes/forbes_group_website/-/commits/branch/default" for 134.121.19.154 at 2021-03-24 22:01:44 +0000
Processing by Projects::CommitsController#show as HTML
Parameters: {"namespace_id"=>"mforbes", "project_id"=>"forbes_group_website", "id"=>"branch/default"}
==> /var/log/gitlab/gitaly/current <==
{"correlation_id":"01F1K4400Y16G9M0J1XE8S30VC","grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.client_name":"gitlab-web","grpc.meta.deadline_type":"regular","grpc.method":"FindAllTagNames","grpc.request.deadline":"2021-03-24T22:01:54.005Z","grpc.request.fullMethod":"/gitaly.RefService/FindAllTagNames","grpc.request.glProjectPath":"mforbes/forbes_group_website","grpc.request.glRepository":"project-56","grpc.request.repoPath":"@hashed/76/88/7688b6ef52555962d008fff894223582c484517cea7da49ee67800adc7fc8866.git","grpc.request.repoStorage":"default","grpc.request.topLevelGroup":"@hashed","grpc.service":"gitaly.RefService","grpc.start_time":"2021-03-24T22:01:44.835Z","grpc.time_ms":59.494,"level":"info","msg":"finished streaming call with code OK","peer.address":"@","pid":2096,"remote_ip":"134.121.19.154","span.kind":"server","system":"grpc","time":"2021-03-24T22:01:44.895Z","username":"mforbes"}
{"correlation_id":"01F1K4400Y16G9M0J1XE8S30VC","grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.client_name":"gitlab-web","grpc.meta.deadline_type":"regular","grpc.method":"FindCommit","grpc.request.deadline":"2021-03-24T22:02:14.097Z","grpc.request.fullMethod":"/gitaly.CommitService/FindCommit","grpc.request.glProjectPath":"mforbes/forbes_group_website","grpc.request.glRepository":"project-56","grpc.request.repoPath":"@hashed/76/88/7688b6ef52555962d008fff894223582c484517cea7da49ee67800adc7fc8866.git","grpc.request.repoStorage":"default","grpc.request.topLevelGroup":"@hashed","grpc.service":"gitaly.CommitService","grpc.start_time":"2021-03-24T22:01:44.897Z","grpc.time_ms":69.954,"level":"info","msg":"finished unary call with code OK","peer.address":"@","pid":2096,"remote_ip":"134.121.19.154","span.kind":"server","system":"grpc","time":"2021-03-24T22:01:44.967Z","username":"mforbes"}
{"correlation_id":"01F1K4400Y16G9M0J1XE8S30VC","grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.client_name":"gitlab-web","grpc.meta.deadline_type":"regular","grpc.method":"FindCommits","grpc.request.deadline":"2021-03-24T22:02:14.078Z","grpc.request.fullMethod":"/gitaly.CommitService/FindCommits","grpc.request.glProjectPath":"mforbes/forbes_group_website","grpc.request.glRepository":"project-56","grpc.request.repoPath":"@hashed/76/88/7688b6ef52555962d008fff894223582c484517cea7da49ee67800adc7fc8866.git","grpc.request.repoStorage":"default","grpc.request.topLevelGroup":"@hashed","grpc.service":"gitaly.CommitService","grpc.start_time":"2021-03-24T22:01:44.978Z","grpc.time_ms":45.31,"level":"info","msg":"finished streaming call with code OK","peer.address":"@","pid":2096,"remote_ip":"134.121.19.154","span.kind":"server","system":"grpc","time":"2021-03-24T22:01:45.023Z","username":"mforbes"}
{"correlation_id":"01F1K4400Y16G9M0J1XE8S30VC","grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.client_name":"gitlab-web","grpc.meta.deadline_type":"regular","grpc.method":"RepositoryExists","grpc.request.deadline":"2021-03-24T22:01:55.008Z","grpc.request.fullMethod":"/gitaly.RepositoryService/RepositoryExists","grpc.request.glProjectPath":"mforbes/forbes_group_website","grpc.request.glRepository":"project-56","grpc.request.repoPath":"@hashed/76/88/7688b6ef52555962d008fff894223582c484517cea7da49ee67800adc7fc8866.git","grpc.request.repoStorage":"default","grpc.request.topLevelGroup":"@hashed","grpc.service":"gitaly.RepositoryService","grpc.start_time":"2021-03-24T22:01:45.299Z","grpc.time_ms":0.129,"level":"info","msg":"finished unary call with code OK","peer.address":"@","pid":2096,"remote_ip":"134.121.19.154","span.kind":"server","system":"grpc","time":"2021-03-24T22:01:45.299Z","username":"mforbes"}
==> /var/log/gitlab/gitlab-rails/production.log <==
Completed 500 Internal Server Error in 503ms (ActiveRecord: 15.7ms | Elasticsearch: 0.0ms | Allocations: 130236)
==> /var/log/gitlab/gitlab-rails/production_json.log <==
{"method":"GET","path":"/mforbes/forbes_group_website/-/commits/branch/default","format":"html","controller":"Projects::CommitsController","action":"show","status":500,"time":"2021-03-24T22:01:45.303Z","params":[{"key":"namespace_id","value":"mforbes"},{"key":"project_id","value":"forbes_group_website"},{"key":"id","value":"branch/default"}],"remote_ip":"134.121.19.154","user_id":2,"username":"mforbes","ua":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.0.2 Safari/605.1.15","correlation_id":"01F1K4400Y16G9M0J1XE8S30VC","meta.user":"mforbes","meta.project":"mforbes/forbes_group_website","meta.root_namespace":"mforbes","meta.caller_id":"Projects::CommitsController#show","meta.remote_ip":"134.121.19.154","meta.feature_category":"source_code_management","gitaly_calls":4,"gitaly_duration_s":0.186025,"redis_calls":58,"redis_duration_s":0.027582,"redis_read_bytes":5723,"redis_write_bytes":7193,"redis_cache_calls":57,"redis_cache_duration_s":0.027215,"redis_cache_read_bytes":5540,"redis_cache_write_bytes":6322,"redis_shared_state_calls":1,"redis_shared_state_duration_s":0.000367,"redis_shared_state_read_bytes":183,"redis_shared_state_write_bytes":871,"db_count":14,"db_write_count":0,"db_cached_count":1,"cpu_s":0.279139,"queue_duration_s":0.043445,"exception.class":"ActionView::Template::Error","exception.message":"undefined method `[]' for nil:NilClass","exception.backtrace":["app/models/commit.rb:80:in `truncate_sha'","app/models/commit.rb:208:in `hpd_short_display_id'","app/views/projects/commits/_commit.html.haml:20","app/views/projects/commits/_commits.html.haml:17","app/models/commit_collection.rb:23:in `<<'","app/models/commit_collection.rb:23:in `each'","app/models/commit_collection.rb:23:in `each'","app/views/projects/commits/_commits.html.haml:10:in `each'","app/views/projects/commits/_commits.html.haml:10:in `each'","app/views/projects/commits/_commits.html.haml:10","app/views/projects/commits/show.html.haml:36","app/controllers/application_controller.rb:125:in `render'","app/controllers/application_controller.rb:555:in `block in allow_gitaly_ref_name_caching'","lib/gitlab/gitaly_client.rb:375:in `allow_ref_name_caching'","app/controllers/application_controller.rb:554:in `allow_gitaly_ref_name_caching'","app/controllers/application_controller.rb:500:in `set_current_admin'","lib/gitlab/session.rb:11:in `with_session'","app/controllers/application_controller.rb:491:in `set_session_storage'","lib/gitlab/i18n.rb:73:in `with_locale'","lib/gitlab/i18n.rb:79:in `with_user_locale'","app/controllers/application_controller.rb:485:in `set_locale'","lib/gitlab/error_tracking.rb:52:in `with_context'","app/controllers/application_controller.rb:550:in `sentry_context'","app/controllers/application_controller.rb:478:in `block in set_current_context'","lib/gitlab/application_context.rb:56:in `block in use'","lib/gitlab/application_context.rb:56:in `use'","lib/gitlab/application_context.rb:22:in `with_context'","app/controllers/application_controller.rb:469:in `set_current_context'","lib/gitlab/metrics/elasticsearch_rack_middleware.rb:16:in `call'","lib/gitlab/middleware/rails_queue_duration.rb:33:in `call'","lib/gitlab/metrics/rack_middleware.rb:16:in `block in call'","lib/gitlab/metrics/transaction.rb:56:in `run'","lib/gitlab/metrics/rack_middleware.rb:16:in `call'","lib/gitlab/request_profiler/middleware.rb:17:in `call'","lib/gitlab/jira/middleware.rb:19:in `call'","lib/gitlab/middleware/go.rb:20:in `call'","lib/gitlab/etag_caching/middleware.rb:21:in `call'","lib/gitlab/middleware/multipart.rb:172:in `call'","lib/gitlab/middleware/read_only/controller.rb:50:in `call'","lib/gitlab/middleware/read_only.rb:18:in `call'","lib/gitlab/middleware/same_site_cookies.rb:27:in `call'","lib/gitlab/middleware/handle_malformed_strings.rb:21:in `call'","lib/gitlab/middleware/basic_health_check.rb:25:in `call'","lib/gitlab/middleware/handle_ip_spoof_attack_error.rb:25:in `call'","lib/gitlab/middleware/request_context.rb:21:in `call'","config/initializers/fix_local_cache_middleware.rb:11:in `call'","lib/gitlab/metrics/requests_rack_middleware.rb:76:in `call'","lib/gitlab/middleware/release_env.rb:12:in `call'"],"db_duration_s":0.01574,"view_duration_s":0.0,"duration_s":0.50345}
==> /var/log/gitlab/gitlab-rails/production.log <==
!n
ActionView::Template::Error (undefined method `[]' for nil:NilClass):
17:
18: - show_project_name = local_assigns.fetch(:show_project_name, false)
19:
20: %li{ class: ["commit flex-row", ("js-toggle-container" if collapsible)], id: "commit-#{commit.hpd_short_display_id}" }
21:
22: .avatar-cell.d-none.d-sm-block
23: = author_avatar(commit, size: 40, has_tooltip: false)
app/models/commit.rb:80:in `truncate_sha'
app/models/commit.rb:208:in `hpd_short_display_id'
app/views/projects/commits/_commit.html.haml:20
app/views/projects/commits/_commits.html.haml:17
app/models/commit_collection.rb:23:in `<<'
app/models/commit_collection.rb:23:in `each'
app/models/commit_collection.rb:23:in `each'
app/views/projects/commits/_commits.html.haml:10:in `each'
app/views/projects/commits/_commits.html.haml:10:in `each'
app/views/projects/commits/_commits.html.haml:10
app/views/projects/commits/show.html.haml:36
app/controllers/application_controller.rb:125:in `render'
app/controllers/application_controller.rb:555:in `block in allow_gitaly_ref_name_caching'
lib/gitlab/gitaly_client.rb:375:in `allow_ref_name_caching'
app/controllers/application_controller.rb:554:in `allow_gitaly_ref_name_caching'
app/controllers/application_controller.rb:500:in `set_current_admin'
lib/gitlab/session.rb:11:in `with_session'
app/controllers/application_controller.rb:491:in `set_session_storage'
lib/gitlab/i18n.rb:73:in `with_locale'
lib/gitlab/i18n.rb:79:in `with_user_locale'
app/controllers/application_controller.rb:485:in `set_locale'
lib/gitlab/error_tracking.rb:52:in `with_context'
app/controllers/application_controller.rb:550:in `sentry_context'
app/controllers/application_controller.rb:478:in `block in set_current_context'
lib/gitlab/application_context.rb:56:in `block in use'
lib/gitlab/application_context.rb:56:in `use'
lib/gitlab/application_context.rb:22:in `with_context'
app/controllers/application_controller.rb:469:in `set_current_context'
lib/gitlab/metrics/elasticsearch_rack_middleware.rb:16:in `call'
lib/gitlab/middleware/rails_queue_duration.rb:33:in `call'
lib/gitlab/metrics/rack_middleware.rb:16:in `block in call'
lib/gitlab/metrics/transaction.rb:56:in `run'
lib/gitlab/metrics/rack_middleware.rb:16:in `call'
lib/gitlab/request_profiler/middleware.rb:17:in `call'
lib/gitlab/jira/middleware.rb:19:in `call'
lib/gitlab/middleware/go.rb:20:in `call'
lib/gitlab/etag_caching/middleware.rb:21:in `call'
lib/gitlab/middleware/multipart.rb:172:in `call'
lib/gitlab/middleware/read_only/controller.rb:50:in `call'
lib/gitlab/middleware/read_only.rb:18:in `call'
lib/gitlab/middleware/same_site_cookies.rb:27:in `call'
lib/gitlab/middleware/handle_malformed_strings.rb:21:in `call'
lib/gitlab/middleware/basic_health_check.rb:25:in `call'
lib/gitlab/middleware/handle_ip_spoof_attack_error.rb:25:in `call'
lib/gitlab/middleware/request_context.rb:21:in `call'
config/initializers/fix_local_cache_middleware.rb:11:in `call'
lib/gitlab/metrics/requests_rack_middleware.rb:76:in `call'
lib/gitlab/middleware/release_env.rb:12:in `call'
==> /var/log/gitlab/nginx/gitlab_access.log <==
134.121.19.154 - - [24/Mar/2021:22:01:45 +0000] "GET /mforbes/forbes_group_website/-/commits/branch/default HTTP/2.0" 500 12146 "https://hg.iscimath.org/mforbes/forbes_group_website/-/tree/branch/default" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.0.2 Safari/605.1.15" -
==> /var/log/gitlab/gitlab-workhorse/current <==
{"content_type":"text/html; charset=utf-8","correlation_id":"01F1K4400Y16G9M0J1XE8S30VC","duration_ms":575,"host":"hg.iscimath.org","level":"info","method":"GET","msg":"access","proto":"HTTP/1.1","referrer":"https://hg.iscimath.org/mforbes/forbes_group_website/-/tree/branch/default","remote_addr":"134.121.19.154:0","remote_ip":"134.121.19.154","route":"","status":500,"system":"http","time":"2021-03-24T22:01:45Z","ttfb_ms":575,"uri":"/mforbes/forbes_group_website/-/commits/branch/default","user_agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.0.2 Safari/605.1.15","written_bytes":12146}
==> /var/log/gitlab/gitaly/gitaly_ruby_json.log <==
{"type":"gitaly-ruby","grpc.start_time":"2021-03-24T22:01:45Z","grpc.time_ms":0.148,"grpc.code":"OK","grpc.method":"Check","grpc.service":"grpc.health.v1.Health","pid":9721,"correlation_id":"c4c935dace0fb5a5d5b7c9821428cc3e","time":"2021-03-24T22:01:45.368Z"}
{"type":"gitaly-ruby","grpc.start_time":"2021-03-24T22:01:45Z","grpc.time_ms":0.284,"grpc.code":"OK","grpc.method":"Check","grpc.service":"grpc.health.v1.Health","pid":23077,"correlation_id":"5ac3fe29fc48552e20a82c2ff11200ea","time":"2021-03-24T22:01:45.369Z"}
Details about the Heptapod instance where the bug occurs
Omnibus docker image octobus/heptapod:0.20.0 running on an AWS instance:
Heptapod = 0.20.0
Mercuria= l5.6.1
hg-evolve = 10.2.0.post1
hg-git = 0.9.0 (dulwich 0.20.19)
GitLab = 13.9.1
Heptapod Shell = 13.16.0
Heptapod Workhorse = 0.20.0
GitLab API = v4
Python = 3.8.8
Ruby = 2.7.2p137
Rails = 6.0.3.4
PostgreSQL = 12.5
Redis = 6.0.10
The following configuration changes have been applied:
#gitlab.rb
external_url "https://hg.iscimath.org"
gitlab_rails['gitlab_shell_ssh_port'] = 11022
gitlab_rails['smtp_enable'] = true
gitlab_rails['smtp_address'] = "smtp..."
gitlab_rails['smtp_port'] = 25 #465
gitlab_rails['smtp_domain'] = "smtp..."
gitlab_rails['smtp_enable_starttls_auto'] = true
nginx['redirect_http_to_https'] = true
letsencrypt['enable'] = true
letsencrypt['contact_emails'] = ["m...@..."] # This should be an array of email addresses to add as contacts
letsencrypt['auto_renew'] = true
letsencrypt['auto_renew_hour'] = 0
letsencrypt['auto_renew_minute'] = nil # Should be a number or cron expression, if specified.
letsencrypt['auto_renew_day_of_month'] = "*/4"
#heptapod.hgrc
[heptapod]
allow-multiple-heads = yes
[logging]
# Does not seem to produce any output... I saw this in
# https://foss.heptapod.net/heptapod/heptapod/-/issues/76#note_927
# and thought it might help me figure out what is causing a problem.
file = /var/log/gitlab/hgserve/mercurial.log