`NoMethodError: undefined method 'session' for #<#<Class:0x00007fa18c446120>:0x00007fa164c84a08>` for API calls to `groups/:group_id/audit_events`

Sentry Issue: STAGINGGITLABCOM-NYB

NoMethodError: undefined method `session' for #<#<Class:0x00007fa18c446120>:0x00007fa164c84a08>
  grape-path-helpers/named_route_matcher.rb:7:in `method_missing'
    return super unless method_id.to_s =~ /_path$/
  api/unique_call_tracking.rb:6:in `visitor_id'
    return context.session[:visitor_id] if context.session[:visitor_id].present?
  api/unique_call_tracking.rb:16:in `track_redis_hll_event'
    return unless visitor_id
  api/unique_call_tracking.rb:22:in `after'
    track_redis_hll_event(@options[:event_name], @options[:feature])
  grape/middleware/base.rb:38:in `call!'
    after_response = after
...
(125 additional frame(s) were not displayed)

NoMethodError: undefined method `session' for #<#<Class:0x00007fa18c446120>:0x00007fa164c84a08>

How to reproduce

https://staging.gitlab.com/api/v4/groups/2132458/audit_events

That group is public.

QA Failure Summary

https://ops.gitlab.net/gitlab-org/quality/staging/-/jobs/1732420

Failures in four tests:

• ./qa/specs/features/ee/browser_ui/1_manage/group/group_audit_logs_1_spec.rb[1:1:2:1:1] # Manage Group Change repository size limit behaves like audit event logs audit events for UI operations
• ./qa/specs/features/ee/browser_ui/1_manage/group/group_audit_logs_1_spec.rb[1:1:5:1:1] # Manage Group Add and remove project access behaves like audit event logs audit events for UI operations
• ./qa/specs/features/ee/browser_ui/1_manage/group/group_audit_logs_1_spec.rb[1:1:4:1:1] # Manage Group Add user, change access level, remove user behaves like audit event logs audit events for UI operations
• ./qa/specs/features/ee/browser_ui/1_manage/group/group_audit_logs_1_spec.rb[1:1:3:1:1] # Manage Group Update group name behaves like audit event logs audit events for UI operations

Stack trace

Similar failures for each test. For example:

  1) Manage Group Change repository size limit behaves like audit event logs audit events for UI operations
     Failure/Error:
       Support::Retrier.retry_until(max_duration: QA::Support::Repeater::DEFAULT_MAX_WAIT_TIME, sleep_interval: 1) do
         get_audit_event_count(group) >= new_event_count
       end
     
     QA::Support::Repeater::WaitExceededError:
       Wait condition not met after 60 seconds
     Shared Example Group: "audit event" called from ./qa/specs/features/ee/browser_ui/1_manage/group/group_audit_logs_1_spec.rb:70
     # ./qa/support/repeater.rb:44:in `repeat_until'
     # ./qa/support/retrier.rb:48:in `retry_until'
     # ./qa/specs/features/ee/browser_ui/1_manage/group/group_audit_logs_1_spec.rb:142:in `wait_for_audit_events'
     # ./qa/specs/features/ee/browser_ui/1_manage/group/group_audit_logs_1_spec.rb:12:in `block (3 levels) in <module:QA>'

Screenshot / HTML page

The failure happens during an API call but the screenshots seem to show the audited event was completed successfully. Not sure if they're helpful but here they are:

Expand for screenshots

manage_group_change_repository_size_limit_behaves_like_audit_event_logs_audit_events_for_ui_operatio.html

manage_group_update_group_name_behaves_like_audit_event_logs_audit_events_for_ui_operations.html

manage_group_add_and_remove_project_access_behaves_like_audit_event_logs_audit_events_for_ui_operati.html

manage_group_add_user_change_access_level_remove_user_behaves_like_audit_event_logs_audit_events_for.html

Possible fixes

Looks like the same failures reported in the discussions in #197972 (closed)

Not sure about a fix, but it might be useful to leave in logging of the count of events if there's a failure.

But the fact that it just started to fail consistently suggests something changed...

changed due date to September 14, 2020

changed milestone to %13.4

added QA Quality devopsmanage failureinvestigating found:staging.gitlab.com priority1 test labels

/cc @dchevalier2

When I run the test against Staging from my machine the API call times out

When logged in and I make the same request via the UI it returns error 500... eventually...

https://staging.gitlab.com/api/v4/groups/2152816/audit_events
{"message":"500 Internal Server Error"}

Sentry logs: https://sentry.gitlab.net/gitlab/staginggitlabcom/issues/1796070

NoMethodError: undefined method `session' for #<#<Class:0x00007fa18c446120>:0x00007fa15fdf5bf8>
  from grape-path-helpers/named_route_matcher.rb:7:in `method_missing'
  from api/unique_call_tracking.rb:6:in `visitor_id'
  from api/unique_call_tracking.rb:16:in `track_redis_hll_event'
  from api/unique_call_tracking.rb:22:in `after'
  from grape/middleware/base.rb:38:in `call!'
  from grape/middleware/base.rb:28:in `call'
  from gitlab/middleware/ip_restrictor.rb:14:in `block in call'
  from gitlab/ip_address_state.rb:10:in `with'
  from gitlab/middleware/ip_restrictor.rb:13:in `call'
  from grape/middleware/base.rb:35:in `call!'
  from grape/middleware/base.rb:28:in `call'
  from rack/oauth2/server/resource.rb:20:in `_call'
  from rack/oauth2/server/resource/bearer.rb:8:in `_call'
  from rack/oauth2/server/abstract/handler.rb:17:in `call'
  from grape/middleware/error.rb:39:in `block in call!'
  from grape/middleware/error.rb:38:in `catch'
  from grape/middleware/error.rb:38:in `call!'
  from grape/middleware/base.rb:28:in `call'
  from grape_logging/middleware/request_logger.rb:60:in `block in call!'
  from grape_logging/middleware/request_logger.rb:58:in `catch'
  from grape_logging/middleware/request_logger.rb:58:in `call!'
  from grape/middleware/base.rb:28:in `call'
  from rack/head.rb:12:in `call'
  from grape/endpoint.rb:231:in `call!'
  from grape/endpoint.rb:225:in `call'
  from grape/router/route.rb:58:in `exec'
  from grape/router.rb:116:in `process_route'
  from grape/router.rb:72:in `block in identity'
  from grape/router.rb:91:in `transaction'
  from grape/router.rb:70:in `identity'
  from grape/router.rb:55:in `block in call'
  from grape/router.rb:132:in `with_optimization'
  from grape/router.rb:54:in `call'
  from grape/api/instance.rb:167:in `call'
  from grape/api/instance.rb:71:in `call!'
  from grape/api/instance.rb:66:in `call'
  from action_dispatch/routing/mapper.rb:19:in `block in <class:Constraints>'
  from action_dispatch/routing/mapper.rb:48:in `serve'
  from action_dispatch/journey/router.rb:49:in `block in serve'
  from action_dispatch/journey/router.rb:32:in `each'
  from action_dispatch/journey/router.rb:32:in `serve'
  from action_dispatch/routing/route_set.rb:834:in `call'
  from omniauth/strategy.rb:192:in `call!'
  from omniauth/strategy.rb:169:in `call'
  from omniauth/strategy.rb:420:in `call_app!'
  from omni_auth/strategies/group_saml.rb:41:in `other_phase'
  from omniauth/strategy.rb:190:in `call!'
  from omniauth/strategy.rb:169:in `call'
  from omniauth/strategy.rb:192:in `call!'
  from omniauth/strategy.rb:169:in `call'
  from omniauth/strategy.rb:192:in `call!'
  from omniauth/strategy.rb:169:in `call'
  from omniauth/strategy.rb:192:in `call!'
  from omniauth/strategy.rb:169:in `call'
  from omniauth/strategy.rb:192:in `call!'
  from omniauth/strategy.rb:169:in `call'
  from gitlab/metrics/elasticsearch_rack_middleware.rb:16:in `call'
  from gitlab/middleware/rails_queue_duration.rb:33:in `call'
  from gitlab/metrics/rack_middleware.rb:16:in `block in call'
  from gitlab/metrics/transaction.rb:61:in `run'
  from gitlab/metrics/rack_middleware.rb:16:in `call'
  from gitlab/request_profiler/middleware.rb:17:in `call'
  from gitlab/database/load_balancing/rack_middleware.rb:39:in `call'
  from labkit/middleware/rack.rb:19:in `block in call'
  from labkit/context.rb:32:in `with_context'
  from labkit/middleware/rack.rb:18:in `call'
  from gitlab/jira/middleware.rb:19:in `call'
  from gitlab/middleware/go.rb:20:in `call'
  from gitlab/etag_caching/middleware.rb:13:in `call'
  from batch_loader/middleware.rb:11:in `call'
  from rack/attack.rb:97:in `call'
  from apollo_upload_server/middleware.rb:20:in `call'
  from gitlab/middleware/multipart.rb:140:in `call'
  from rack/attack.rb:111:in `call'
  from warden/manager.rb:36:in `block in call'
  from warden/manager.rb:34:in `catch'
  from warden/manager.rb:34:in `call'
  from rack/cors.rb:98:in `call'
  from rack/tempfile_reaper.rb:15:in `call'
  from rack/etag.rb:25:in `call'
  from rack/conditional_get.rb:25:in `call'
  from rack/head.rb:12:in `call'
  from action_dispatch/http/content_security_policy.rb:18:in `call'
  from gitlab/middleware/read_only/controller.rb:51:in `call'
  from gitlab/middleware/read_only.rb:18:in `call'
  from rack/session/abstract/id.rb:259:in `context'
  from rack/session/abstract/id.rb:253:in `call'
  from action_dispatch/middleware/cookies.rb:648:in `call'
  from gitlab/middleware/same_site_cookies.rb:27:in `call'
  from action_dispatch/middleware/callbacks.rb:27:in `block in call'
  from active_support/callbacks.rb:101:in `run_callbacks'
  from action_dispatch/middleware/callbacks.rb:26:in `call'
  from action_dispatch/middleware/actionable_exceptions.rb:17:in `call'
  from action_dispatch/middleware/debug_exceptions.rb:32:in `call'
  from action_dispatch/middleware/show_exceptions.rb:33:in `call'
  from gitlab/middleware/basic_health_check.rb:25:in `call'
  from lograge/rails_ext/rack/logger.rb:15:in `call_app'
  from rails/rack/logger.rb:26:in `block in call'
  from active_support/tagged_logging.rb:80:in `block in tagged'
  from active_support/tagged_logging.rb:28:in `tagged'
  from active_support/tagged_logging.rb:80:in `tagged'
  from rails/rack/logger.rb:26:in `call'
  from action_dispatch/middleware/remote_ip.rb:81:in `call'
  from gitlab/middleware/handle_ip_spoof_attack_error.rb:25:in `call'
  from gitlab/middleware/request_context.rb:23:in `call'
  from request_store/middleware.rb:19:in `call'
  from action_dispatch/middleware/request_id.rb:27:in `call'
  from rack/method_override.rb:22:in `call'
  from rack/runtime.rb:22:in `call'
  from rack/timeout/core.rb:123:in `block in call'
  from rack/timeout/support/timeout.rb:19:in `timeout'
  from rack/timeout/core.rb:122:in `call'
  from /opt/gitlab/embedded/service/gitlab-rails/config/initializers/fix_local_cache_middleware.rb:9:in `call'
  from action_dispatch/middleware/executor.rb:14:in `call'
  from rack/sendfile.rb:111:in `call'
  from action_dispatch/middleware/host_authorization.rb:76:in `call'
  from gitlab/metrics/requests_rack_middleware.rb:60:in `call'
  from raven/integrations/rack.rb:51:in `call'
  from rails/engine.rb:527:in `call'
  from rails/railtie.rb:190:in `public_send'
  from rails/railtie.rb:190:in `method_missing'
  from gitlab/middleware/release_env.rb:12:in `call'
  from rack/urlmap.rb:68:in `block in call'
  from rack/urlmap.rb:53:in `each'
  from rack/urlmap.rb:53:in `call'
  from puma/configuration.rb:228:in `call'
  from puma/server.rb:722:in `handle_request'
  from puma/server.rb:481:in `process_client'
  from puma/server.rb:335:in `block in run'
  from puma/thread_pool.rb:138:in `block in spawn_thread'

Possible cause: !39616 (merged)

HTTP 500 shown in screenshot of https://ops.gitlab.net/gitlab-org/quality/staging/-/jobs/1783147, same test but different failure (trying to click an element when the 500 error page is shown)

added [deprecated] Accepting merge requests label

added typebug label and removed failureinvestigating label

changed title from Failures in qa/specs/features/ee/browser_ui/1_manage/group/group_audit_logs_1_spec | Four "audit event logs audit events for UI operations" tests | Timing out while waiting for expected event count to {+NoMethodError: undefined method 'session' for #<#<Class:0x00007fa18c446120>:0x00007fa164c84a08> for API calls to groups/:group_id/audit_events+}

changed the description

removed priority1 label

removed QA test labels

mentioned in issue gitlab-org/quality/pipeline-triage#44 (closed)

changed the description

added sectiondev label

assigned to @tancnle

mentioned in merge request !40921 (merged)

I am unable to reproduce it locally, even with feature flag track_unique_visit and usage ping settings enabled

Sentry log on Gitlab.com

added priority2 severity2 labels

marked this issue as related to gitlab-org/quality/pipeline-triage#44 (closed)

mentioned in commit ec9a65c5

removed [deprecated] Accepting merge requests label

mentioned in issue gitlab-org/quality/pipeline-triage#45 (closed)

@tancnle I'm going to reassign this to me to investigate further. I'm unable to reproduce locally yet!

assigned to @mwoolf and unassigned @tancnle

mentioned in merge request !41689 (merged)

marked this issue as related to gitlab-org/quality/pipeline-triage#45 (closed)

Since this was reverted and the permanent fix for it is in maintainer review, I'll close this issue in favor of the original issue.

closed