health_check unusable as of self-changing token

Added ~12980 label

Same behaviour here.

@twk3 Any ideas how this could happen?

I haven't been able to reproduce this issue yet. @fsedarkalex can you also take note of the runners registration token listed in ->Admin->Runners, and the next time the health check token changes on you, can you let me know if the runner token changed as well?

Other than the reset button, the token is only otherwise supposed to be generated if the entry in the database for it is blank.

@twk3 this is strange... it happened several times per hour yesterday and now it didn't happen since 90 minutes... I will try some things later...

@ycezard what about you?

I have juste reactivated my shinken checks to test (I had disabled it cause it was unusable like this). I have written down the actual health check token and the runner one too, I'll check them when shinken will start complaining again (it happened at least 3 times yesterday, so I am pretty sure it will happen again).

For me there is one notable difference between today and yesterday. Yesterday I was pullin/pushing/merging actively today I don't do such things. Maybe there is a relation... Thisis what I am testing now...

The nginx log for yesterday show when the error appeared :

SHINKEN_IP - - [23/May/2016:17:01:44 +0200] "GET /health_check/database?token=UhafQVo37yEE-Ph6PxSb HTTP/1.1" 200 7 "-" "check_http/v1.5 (nagios-plugins 1.5)"
SHINKEN_IP - - [23/May/2016:17:07:25 +0200] "GET /health_check?token=UhafQVo37yEE-Ph6PxSb HTTP/1.1" 404 2287 "-" "check_http/v1.5 (nagios-plugins 1.5)"
SHINKEN_IP - - [23/May/2016:17:07:45 +0200] "GET /health_check/cache?token=UhafQVo37yEE-Ph6PxSb HTTP/1.1" 404 2287 "-" "check_http/v1.5 (nagios-plugins 1.5)"

There are no logs (so no external http/https access) between the two first lines.

One more hint from my side: I did a gitlab-ctl reconfigure && gitlab-ctl restart yesterday evening and did not monitor this issue anymore since then until today... probably that solved the issue?

We are having similar issues, I'll try to get more details.

Took some time but it did it again. The Health Check token has changed in Health Check (without any external action). @twk3 The Runner Registration Token did not change.

I used the reconfigure/restart technique propopsed by @fsedarkalex, and it's been holding for 3+ hours so far.

Would love to report progress but (damn vmware + adaptec) my server is down

Happened again here. Server was running from 8p.m. yesterday and it happened again some minutes ago (around 16 hours later) health-token changed, runner-reg-token didn't.

further I can now say the token definitely is saved into DB as after a reboot of the server the key still kept being the old one.

Just a confirmation; I operate two GitLab servers (CE, Omnibus edition). Yesterday I changed our Smokeping monitor to poll the new /health_check paths with the access tokens (one for each server) that I got from the Web interface. Then during the night I started receiving alerts because the token has changed on one server. Today it happened on the other server. No idea what may have provoked the change. If there's anything I can do to help, please let me know.

probably useful: did you update both at the same time? Or did it probably happen after the same time after upgrade on both servers?

@twk3 I have a customer reporting this in https://gitlab.zendesk.com/agent/tickets/25042. I'm also unable to reproduce, though. Seems it's a problem somehow

@fsedarkalex: I updated both GitLab instances at about the same time: 2016-05-23T06:16:43Z on one system, 2016-05-23T06:19:50Z on the other. I started monitoring the /health_check?token=... URLs on both systems at 2016-05-24_17:51Z. On one system, the requests started failing (presumably because the tokens changed) at 2016-05-24T20:51:22Z, on the other at 2016-05-25 08:40:23Z.

mentioned in issue #17892 (closed)

We have 2 Gitlab Instances (both are basically Debian 8 + Gitlab CE Omnibus Package. The issue did never occur on one of the instances. On the other one the issue is now gone since more than a day by doing the following: I manually reset the health_check token in the web interface and ran gitlab-ctl reconfigure && gitlab-ctl restart

Same here, a manual gitlab-ctl reconfigure && gitlab-ctl restart fixed the problem on our two GitLab servers (Debian Jessie, GitLab 8.8.2 CE Omnibus). Now running for more than 24hrs without resetting the access token. Before, on both servers, the access token was reset every 1-4h.

I've been combing over the implementation and haven't found anything. Quite the mystery.

I've reproduced this too. It seems that after a variable number of GET requests, the token changes:

Started GET "/health_check?token=[FILTERED]" for x.x.x.x at 2016-05-27 00:50:06 -0400
Started GET "/health_check?token=[FILTERED]" for x.x.x.x at 2016-05-27 00:50:16 -0400
Started GET "/health_check?token=[FILTERED]" for x.x.x.x at 2016-05-27 00:50:26 -0400
Started GET "/health_check?token=[FILTERED]" for x.x.x.x at 2016-05-27 00:50:37 -0400
Started GET "/health_check?token=[FILTERED]" for x.x.x.x at 2016-05-27 00:50:47 -0400
Started GET "/health_check?token=[FILTERED]" for x.x.x.x at 2016-05-27 00:50:57 -0400
Started GET "/health_check?token=[FILTERED]" for x.x.x.x at 2016-05-27 00:51:07 -0400
Started GET "/health_check?token=[FILTERED]" for x.x.x.x at 2016-05-27 00:51:17 -0400
Started GET "/health_check?token=[FILTERED]" for x.x.x.x at 2016-05-27 00:51:27 -0400
Filter chain halted as :validate_health_check_access! rendered or redirected

I just restarted unicorn (sudo gitlab-ctl restart unicorn), and the problem went away. But then I went into the database and set the token to NULL and restarted unicorn again:

gitlabhq_production=>UPDATE application_settings SET health_check_access_token = NULL;
UPDATE 1

I added some debugging to display the value of the token in HealthCheckController#token_valid? before and after. After running a script to hit this endpoint periodically, I see:

Started GET "/health_check?token=[FILTERED]" for x.x.x.x at 2016-05-27 01:55:35 -0400
Processing by HealthCheckController#index as */*
  Parameters: {"token"=>"[FILTERED]"}
=== Before token: 7oFuBvpk6gnxgRDCZMSH
=== After token: 7oFuBvpk6gnxgRDCZMSH
Completed 200 OK in 126ms (Views: 2.0ms | ActiveRecord: 4.4ms)
Started GET "/health_check?token=[FILTERED]" for x.x.x.x at 2016-05-27 01:55:46 -0400
Processing by HealthCheckController#index as */*
  Parameters: {"token"=>"[FILTERED]"}
=== Before token: MKpts93YgiKpRKKZDpxp
=== After token: MKpts93YgiKpRKKZDpxp

Another words, the problem seems to show up when the initial value is NULL. After I restarted unicorn again, the token did not change.

I'm thinking the problem has to be here: https://gitlab.com/gitlab-org/gitlab-ce/blob/master/app/models/concerns/token_authenticatable.rb#L21

Somehow the read_attribute call must be returning a blank value, even after the token gets updated.

There is also a cache invalidation issue with application settings when this token changes, but that's a separate issue.

Actually, I think there is some cache issue going on here. Here's what I see:

One GET request updates the token properly and sets updated_at = 2016-05-27 07:17:46
Subsequent GET request looks at application settings and sees the token blank and resets it. I examined updated_at = 2016-05-27 06:54:41. This is stale!

Somehow the cache invalidation/retrieval of the latest settings isn't working as expected.

@stanhu Awesome, now I can repro it.

My guess here is that a gitlab-ctl restart is what works around the issue for people, as the token will finally at that point make it into the unicorn master.

The actual issue looks to me to be the RequestStore in Gitlab::CurrentSettings https://gitlab.com/gitlab-org/gitlab-ce/blob/master/lib/gitlab/current_settings.rb#L6

Right! Can we get rid of RequestStore there? We already have a Redis cache for the settings, and RequestStore may not do invalidations properly across different unicorn workers.

Clearing requeststore in unicorn.rb's after_fork appears to fix the issue

after_fork do |server, worker|
  RequestStore.clear!
end

mentioned in merge request !4332 (merged)

Milestone changed to %8.8

mentioned in issue #17519 (closed)

Status changed to closed by merge request !4332 (merged)

health_check unusable as of self-changing token

Summary

Steps to reproduce

Expected behavior

Relevant logs and/or screenshots

Output of checks

Results of GitLab Application Check

Results of GitLab Environment Info

Possible fixes

Designs

Child items ...

Activity

Admin message

Admin message

health_check unusable as of self-changing token

Summary

Steps to reproduce

Expected behavior

Relevant logs and/or screenshots

Output of checks

Results of GitLab Application Check

Results of GitLab Environment Info

Possible fixes

Activity