GitLab

Created by: maoueh

Sometimes, in our Gitlab instance running on 6.4.3, we receives a 404 error page after creating a new issue. The 404 seems to occur when redirecting to the actual issue. Here the relevant part from production.log (with some information replaced):

Processing by Projects::IssuesController#create as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"51lpqiNKqtxUPjP5gLag8BK2UWBUVFMRXQapkn+Z+XU=", "issue"=>{"title"=>"sessi time out not kicked out", "assignee_id"=>"14", "milestone_id"=>"", "label_list"=>"label, ", "description"=>"It is still possible to ... (text removed for brievity\r\n\r\n....\r\n...."}, "project_id"=>"company/project"}
Redirected to http://our.hostname/company/project/issues/101
Completed 302 Found in 458ms (ActiveRecord: 18.3ms)
Started GET "/company/project/issues/101" for 127.0.0.1 at 2014-01-02 14:43:10 -0500
Processing by Projects::IssuesController#show as HTML
  Parameters: {"project_id"=>"company/project", "id"=>"101"}

ActiveRecord::RecordNotFound (ActiveRecord::RecordNotFound):
  app/controllers/projects/issues_controller.rb:134:in `redirect_old'
  app/controllers/projects/issues_controller.rb:102:in `rescue in issue'
  app/controllers/projects/issues_controller.rb:99:in `issue'
  app/controllers/application_controller.rb:57:in `set_current_user_for_thread'

  Rendered errors/not_found.html.haml within layouts/errors (0.2ms)
  Rendered layouts/_head.html.haml (2.8ms)
  Rendered layouts/_search.html.haml (39.7ms)
  Rendered layouts/_head_panel.html.haml (45.7ms)
  Rendered layouts/_flash.html.haml (0.2ms)
Completed 404 Not Found in 116ms (Views: 46.3ms | ActiveRecord: 13.0ms)

Sometimes, the user can re-create the issue right way, sometimes it take more tries. What seems strange from the log is that it looks like the issue is created correctly but it does not exist in the database at the time the redirect occurs. For the production log, the id used for redirect is the iid set to 101. For sidekiq, it's the overall id used, which should have been 286 in this case:

2014-01-03T03:04:29Z 1876 TID-qexck Sidekiq::Extensions::DelayedMailer JID-489115fdcf2cf122cdcf0ae9 INFO: start
2014-01-03T03:04:29Z 1876 TID-qexck Sidekiq::Extensions::DelayedMailer JID-489115fdcf2cf122cdcf0ae9 INFO: fail: 0.034 sec
2014-01-03T03:04:29Z 1876 TID-qexck WARN: {"retry"=>true, "queue"=>"default", "class"=>"Sidekiq::Extensions::DelayedMailer", "args"=>["---\n- !ruby/class 'Notify'\n- :send\n- - new_issue_email\n  - 14\n  - 286\n"], "jid"=>"489115fdcf2cf122cdcf0ae9", "enqueued_at"=>1388691790.4912586, "error_message"=>"Couldn't find Issue with id=286", "error_class"=>"ActiveRecord::RecordNotFound", "failed_at"=>"2014-01-02T19:43:27Z", "retry_count"=>11, "retried_at"=>2014-01-03 03:04:29 UTC}
2014-01-03T03:04:29Z 1876 TID-qexck WARN: Couldn't find Issue with id=286
2014-01-03T03:04:29Z 1876 TID-qexck WARN: /data/git/gitlab/vendor/bundle/ruby/1.9.1/gems/activerecord-4.0.2/lib/active_record/relation/finder_methods.rb:198:in `raise_record_not_found_exception!'
/data/git/gitlab/vendor/bundle/ruby/1.9.1/gems/activerecord-4.0.2/lib/active_record/relation/finder_methods.rb:284:in `find_one'
/data/git/gitlab/vendor/bundle/ruby/1.9.1/gems/activerecord-4.0.2/lib/active_record/relation/finder_methods.rb:268:in `find_with_ids'
/data/git/gitlab/vendor/bundle/ruby/1.9.1/gems/activerecord-4.0.2/lib/active_record/relation/finder_methods.rb:35:in `find'
/data/git/gitlab/vendor/bundle/ruby/1.9.1/gems/activerecord-deprecated_finders-1.0.3/lib/active_record/deprecated_finders/relation.rb:122:in `find'
/data/git/gitlab/vendor/bundle/ruby/1.9.1/gems/activerecord-4.0.2/lib/active_record/querying.rb:3:in `find'
/data/git/gitlab/app/mailers/emails/issues.rb:4:in `new_issue_email'
/data/git/gitlab/vendor/bundle/ruby/1.9.1/gems/actionpack-4.0.2/lib/abstract_controller/base.rb:189:in `process_action'

But what's really strange is that mysql decided to increment the table id. Indeed, there is now gaps in the ids of the issues table, 4 exactly. Does something deleted the issue between the initial save and the redirect? Seems odd to me. Here a small subset of the issues table (select id, iid, project_id from issues;):

...
| 282 |   22 |         15 |
| 283 |   99 |         65 |
| 284 |   23 |         15 |
| 285 |  100 |         65 |
| 287 |  101 |         65 |
+-----+------+------------+
283 rows in set (0.00 sec)

As you can see, there is 283 rows, but the current id is 287 which points us that 4 issues resulted in a 404 error page for the user. The log pasted above happened between issue 285 and 287 on project id 65 (the 287 being the second successful try).

Even if there is a gap between table ids, there is none for iid, probably because handled correctly directly in Gitlab. (select id, iid from issues where project_id = 65;):

...
| 283 |   99 |
| 285 |  100 |
| 287 |  101 |
+-----+------+
101 rows in set (0.00 sec)

Another strange things is that user reported that for the second try, the auto completion of Gitlab proposed is last entered title (the one entered just before seeing the 404 error page). So, it seems some stuff are saved somehow, maybe via a hook.

Looking in the mysqld.log, nothing revelant where present. I looked at the IssueController code but saw nothing in it directly that could cause the issue to not be saved correctly.

If I could somehow increase production log level somehow, maybe I could more of what is going on there.

Regards, Matt