Integrations Webhooks not working - Error 500
Summary
After an update from 10.5.4-ce.0 to 10.5.6-ce.0 the Webhooks aren't working anymore. Triggering a Webhook results in a 500 Internal Server Error of GitLab.
Steps to reproduce
- Creating a new custom webhock to a local URL (same network as the gitlab installation)
- Trigger a event by push or test button
What is the current bug behavior?
Nothing happens if a Webhook gets triggert. Triggering a Webhook test results in a 500 Internal Server Error.
What is the expected correct behavior?
The Webhook gets called correctly or if it fails send a notification or e-mail to the admin/project manager.
Relevant logs and/or screenshots
LOG:
==> /var/log/gitlab/logrotate/state <==
==> /var/log/gitlab/gitlab-workhorse/current <==
2018-03-21_12:20:00.48978 gitlab.company.local @ - - [2018-03-21 13:20:00.488744967 +0100 CET m=+16696.458053206] "POST /api/v4/jobs/request HTTP/1.1" 204 0 "" "gitlab-runner 10.5.0 (10-5-stable; go1.8.5; linux/arm)" 0.000697
==> /var/log/gitlab/nginx/gitlab_access.log <==
192.168.1.14 - - [21/Mar/2018:13:20:00 +0100] "POST /api/v4/jobs/request HTTP/1.1" 204 0 "" "gitlab-runner 10.5.0 (10-5-stable; go1.8.5; linux/arm)"
==> /var/log/gitlab/gitlab-monitor/current <==
2018-03-21_12:20:03.33986 ::1 - - [21/Mar/2018:13:20:03 CET] "GET /sidekiq HTTP/1.1" 200 12688
2018-03-21_12:20:03.33992 - -> /sidekiq
==> /var/log/gitlab/gitlab-workhorse/current <==
2018-03-21_12:20:03.49020 gitlab.company.local @ - - [2018-03-21 13:20:03.48948238 +0100 CET m=+16699.458790632] "POST /api/v4/jobs/request HTTP/1.1" 204 0 "" "gitlab-runner 10.5.0 (10-5-stable; go1.8.5; linux/arm)" 0.000487
==> /var/log/gitlab/nginx/gitlab_access.log <==
192.168.1.14 - - [21/Mar/2018:13:20:03 +0100] "POST /api/v4/jobs/request HTTP/1.1" 204 0 "" "gitlab-runner 10.5.0 (10-5-stable; go1.8.5; linux/arm)"
==> /var/log/gitlab/sidekiq/current <==
2018-03-21_12:20:03.83979 127.0.0.1 - - [21/Mar/2018:13:20:03 CET] "GET /metrics HTTP/1.1" 200 25
2018-03-21_12:20:03.84031 - -> /metrics
==> /var/log/gitlab/gitlab-monitor/current <==
2018-03-21_12:20:05.37172 ::1 - - [21/Mar/2018:13:20:05 CET] "GET /database HTTP/1.1" 200 55052
2018-03-21_12:20:05.37177 - -> /database
==> /var/log/gitlab/gitlab-workhorse/current <==
2018-03-21_12:20:06.49030 gitlab.company.local @ - - [2018-03-21 13:20:06.489246645 +0100 CET m=+16702.458554895] "POST /api/v4/jobs/request HTTP/1.1" 204 0 "" "gitlab-runner 10.5.0 (10-5-stable; go1.8.5; linux/arm)" 0.000816
==> /var/log/gitlab/nginx/gitlab_access.log <==
192.168.1.14 - - [21/Mar/2018:13:20:06 +0100] "POST /api/v4/jobs/request HTTP/1.1" 204 0 "" "gitlab-runner 10.5.0 (10-5-stable; go1.8.5; linux/arm)"
==> /var/log/gitlab/gitlab-monitor/current <==
2018-03-21_12:20:07.46630 ::1 - - [21/Mar/2018:13:20:07 CET] "GET /process HTTP/1.1" 200 1512
2018-03-21_12:20:07.46693 - -> /process
==> /var/log/gitlab/sidekiq/current <==
2018-03-21_12:20:08.06282 2018-03-21T12:20:08.062Z 32511 TID-otkjounro RepositoryCheck::BatchWorker JID-32d90287af5f310c22aab0b5 INFO: start
2018-03-21_12:20:08.19635 2018-03-21T12:20:08.196Z 32511 TID-otkjounro RepositoryCheck::BatchWorker JID-32d90287af5f310c22aab0b5 INFO: done: 0.133 sec
==> /var/log/gitlab/gitlab-rails/production.log <==
Started GET "/Dev/project1/hooks/5/test?trigger=push_events" for 192.168.1.10 at 2018-03-21 13:20:09 +0100
==> /var/log/gitlab/gitlab-workhorse/current <==
2018-03-21_12:20:09.49353 gitlab.company.local @ - - [2018-03-21 13:20:09.490070089 +0100 CET m=+16705.459378339] "POST /api/v4/jobs/request HTTP/1.1" 204 0 "" "gitlab-runner 10.5.0 (10-5-stable; go1.8.5; linux/arm)" 0.003197
==> /var/log/gitlab/nginx/gitlab_access.log <==
192.168.1.14 - - [21/Mar/2018:13:20:09 +0100] "POST /api/v4/jobs/request HTTP/1.1" 204 0 "" "gitlab-runner 10.5.0 (10-5-stable; go1.8.5; linux/arm)"
==> /var/log/gitlab/gitlab-rails/production.log <==
Processing by Projects::HooksController#test as HTML
Parameters: {"trigger"=>"push_events", "namespace_id"=>"Dev", "project_id"=>"project1", "id"=>"5"}
Completed 500 Internal Server Error in 168ms (ActiveRecord: 8.8ms)
==> /var/log/gitlab/gitlab-rails/production_json.log <==
{"method":"GET","path":"/Dev/project1/hooks/5/test","format":"html","controller":"Projects::HooksController","action":"test","status":500,"error":"URI::InvalidURIError: URI::InvalidURIError","duration":171.7,"view":0.0,"db":8.85,"time":"2018-03-21T12:20:09.544Z","params":[{"key":"trigger","value":"push_events"},{"key":"namespace_id","value":"Dev"},{"key":"project_id","value":"project1"},{"key":"id","value":"5"}],"remote_ip":"192.168.1.10","user_id":3,"username":"sm","gitaly_calls":4}
==> /var/log/gitlab/gitlab-rails/production.log <==
URI::InvalidURIError (URI::InvalidURIError):
lib/gitlab/proxy_http_connection_adapter.rb:14:in `connection'
app/services/web_hook_service.rb:73:in `make_request'
app/services/web_hook_service.rb:26:in `execute'
app/models/hooks/web_hook.rb:10:in `execute'
app/services/test_hooks/base_service.rb:22:in `block in execute'
app/services/test_hooks/base_service.rb:19:in `catch'
app/services/test_hooks/base_service.rb:19:in `execute'
app/controllers/projects/hooks_controller.rb:41:in `test'
lib/gitlab/i18n.rb:47:in `with_locale'
lib/gitlab/i18n.rb:53:in `with_user_locale'
app/controllers/application_controller.rb:325:in `set_locale'
lib/gitlab/middleware/multipart.rb:95:in `call'
lib/gitlab/request_profiler/middleware.rb:14:in `call'
lib/gitlab/middleware/go.rb:17:in `call'
lib/gitlab/etag_caching/middleware.rb:11:in `call'
lib/gitlab/middleware/read_only.rb:31:in `call'
lib/gitlab/request_context.rb:18:in `call'
lib/gitlab/metrics/requests_rack_middleware.rb:27:in `call'
==> /var/log/gitlab/gitlab-workhorse/current <==
2018-03-21_12:20:09.72333 gitlab.company.local @ - - [2018-03-21 13:20:09.490096417 +0100 CET m=+16705.459404643] "GET /Dev/project1/hooks/5/test?trigger=push_events HTTP/1.1" 500 2902 "http://gitlab.company.local/Dev/project1/settings/integrations" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:60.0) Gecko/20100101 Firefox/60.0" 0.233074
==> /var/log/gitlab/nginx/gitlab_access.log <==
192.168.1.10 - - [21/Mar/2018:13:20:09 +0100] "GET /Dev/project1/hooks/5/test?trigger=push_events HTTP/1.1" 500 2902 "http://gitlab.company.local/Dev/project1/settings/integrations" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:60.0) Gecko/20100101 Firefox/60.0"
==> /var/log/gitlab/gitlab-workhorse/current <==
2018-03-21_12:20:09.96262 2018/03/21 13:20:09 Send static file "/opt/gitlab/embedded/service/gitlab-rails/public/favicon.ico" ("") for GET "/favicon.ico"
2018-03-21_12:20:09.96267 gitlab.company.local @ - - [2018-03-21 13:20:09.962036934 +0100 CET m=+16705.931345125] "GET /favicon.ico HTTP/1.1" 200 5430 "" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:60.0) Gecko/20100101 Firefox/60.0" 0.000369
==> /var/log/gitlab/nginx/gitlab_access.log <==
192.168.1.10 - - [21/Mar/2018:13:20:09 +0100] "GET /favicon.ico HTTP/1.1" 200 5430 "" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:60.0) Gecko/20100101 Firefox/60.0"
==> /var/log/gitlab/gitlab-rails/production.log <==
Started GET "/-/metrics" for 127.0.0.1 at 2018-03-21 13:20:11 +0100
Processing by MetricsController#index as HTML
Completed 200 OK in 4ms (Views: 0.9ms | ActiveRecord: 0.0ms)
==> /var/log/gitlab/gitlab-rails/production_json.log <==
{"method":"GET","path":"/-/metrics","format":"html","controller":"MetricsController","action":"index","status":200,"duration":7.78,"view":0.86,"db":0.0,"time":"2018-03-21T12:20:11.327Z","params":[],"remote_ip":null,"user_id":null,"username":null}
/opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/omnibus-ctl-0.5.0/lib/omnibus-ctl.rb:576:in `system': Interrupt
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/omnibus-ctl-0.5.0/lib/omnibus-ctl.rb:576:in `tail'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/omnibus-ctl-0.5.0/lib/omnibus-ctl.rb:730:in `run'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/omnibus-ctl-0.5.0/bin/omnibus-ctl:31:in `<top (required)>'
from /opt/gitlab/embedded/bin/omnibus-ctl:23:in `load'
from /opt/gitlab/embedded/bin/omnibus-ctl:23:in `<main>'
^C
No Webook aktivity since the update.
Output of checks
Local gitlab-ce installation on debian 9 with apt repository packages.gitlab.com.
Results of GitLab environment info
Expand for output related to GitLab environment info
System information System: Debian 9.4 Current User: git Using RVM: no Ruby Version: 2.3.6p384 Gem Version: 2.6.13 Bundler Version:1.13.7 Rake Version: 12.3.0 Redis Version: 3.2.11 Git Version: 2.14.3 Sidekiq Version:5.0.5 Go Version: unknownGitLab information Version: 10.5.6 Revision: 4b41d48 Directory: /opt/gitlab/embedded/service/gitlab-rails DB Adapter: postgresql URL: http://GitLab.company.local HTTP Clone URL: http://GitLab.company.local/some-group/some-project.git SSH Clone URL: git@GitLab.company.local:some-group/some-project.git Using LDAP: no Using Omniauth: no
GitLab Shell Version: 6.0.3 Repository storage paths:
- default: /mnt/nas/git-data/repositories Hooks: /opt/gitlab/embedded/service/gitlab-shell/hooks Git: /opt/gitlab/embedded/bin/git
Results of GitLab application Check
Expand for output related to the GitLab application check
Checking GitLab Shell ...GitLab Shell version >= 6.0.3 ? ... OK (6.0.3) Repo base directory exists? default... yes Repo storage directories are symlinks? default... no Repo paths owned by git:root, or git:git? default... yes Repo paths access is drwxrws---? default... yes hooks directories in repos are links: ... 5/5 ... ok 5/6 ... ok 5/7 ... ok 5/8 ... ok 5/9 ... repository is empty 5/10 ... ok 5/11 ... repository is empty 5/12 ... ok 5/13 ... ok 5/14 ... ok 5/15 ... ok 5/16 ... ok 5/17 ... ok 3/18 ... ok 5/19 ... ok 5/20 ... ok 5/21 ... ok Running /opt/gitlab/embedded/service/gitlab-shell/bin/check Check GitLab API access: OK Redis available via internal API: OK
Access to /var/opt/gitlab/.ssh/authorized_keys: OK gitlab-shell self-check successful
Checking GitLab Shell ... Finished
Checking Sidekiq ...
Running? ... yes Number of Sidekiq processes ... 1
Checking Sidekiq ... Finished
Reply by email is disabled in config/gitlab.yml Checking LDAP ...
LDAP is disabled in config/gitlab.yml
Checking LDAP ... Finished
Checking GitLab ...
Git configured correctly? ... yes Database config exists? ... yes All migrations up? ... yes Database contains orphaned GroupMembers? ... no GitLab config exists? ... yes GitLab config up to date? ... yes Log directory writable? ... yes Tmp directory writable? ... yes Uploads directory exists? ... yes Uploads directory has correct permissions? ... yes Uploads directory tmp has correct permissions? ... yes Init script exists? ... skipped (omnibus-gitlab has no init script) Init script up-to-date? ... skipped (omnibus-gitlab has no init script) Projects have namespace: ... 5/5 ... yes 5/6 ... yes 5/7 ... yes 5/8 ... yes 5/9 ... yes 5/10 ... yes 5/11 ... yes 5/12 ... yes 5/13 ... yes 5/14 ... yes 5/15 ... yes 5/16 ... yes 5/17 ... yes 3/18 ... yes 5/19 ... yes 5/20 ... yes 5/21 ... yes Redis version >= 2.8.0? ... yes Ruby version >= 2.3.5 ? ... yes (2.3.6) Git version >= 2.9.5 ? ... yes (2.14.3) Git user has default SSH configuration? ... yes Active users: ... 12
Checking GitLab ... Finished
Good to know
During the upate (apt update; apt upgrade) only gitlab-ce was updated:
/var/log/apt/history.log
Start-Date: 2018-03-21 08:24:12
Commandline: apt upgrade
Requested-By: sm (1000)
Upgrade: gitlab-ce:amd64 (10.5.4-ce.0, 10.5.6-ce.0)
End-Date: 2018-03-21 08:41:53
So a assume that all other system components are working. If I call the Webhook URL from a browser in the same Network or from the gitlab server shell with curl, the target URL gets called without any issue.
Restarting gitlab with sudo gitlab-ctl restart
has not solved the problem.