search

department-of-veterans-affairs / va.gov-team

Public resources for building on and in support of VA.gov. Visit complete Knowledge Hub:
https://depo-platform-documentation.scrollhelp.site/index.html
281 stars 198 forks source link

Loadtesting tool to generate authenticated sessions does not generate valid sessions #758

Closed zurbergram closed 5 years ago

zurbergram commented 5 years ago

Status

UNRESOLVED

Severity Analysis

Estimate of how critical this bug is

User Impact

Description

There seems to be an issue with the generation of cookies for authentication from the job http://jenkins.vfs.va.gov/job/rake_tasks/job/vets-api-load-test-sessions/ for use with load testing https://github.com/department-of-veterans-affairs/devops/blob/master/loadtest/education_benefits_claim_1995_stem/README.md

In the instructions for running load tests against vets-api endpoints it says to do the following

In order to generate authenticated sessions, use [this Jenkins task](http://jenkins.vfs.va.gov/job/rake_tasks/job/vets-api-load-test-sessions/).

1. click "Build with Parameters" on the left (if you do not see this link, double-check that you're logged in)
2. click "Build" (no rake_params are required)
3. click on your build and select "Console Output" on the left
4. look for the array of hashes with the keys `"uuid"` and `"cookie_header"`
5. copy this array and paste it into a new file called `./sessions.json` and save it in the same directory as the locust file `form1995_stem_locust.py` (next to this README).
6. clean up the array so it looks like:

However these don't seem to generate valid cookie_headers of api_session and vagov_session_staging.

To test this I went to https://staging.va.gov/education/apply-for-education-benefits/application/1995/applicant/information

Steps to Reproduce

follow instructions at https://github.com/department-of-veterans-affairs/devops/blob/master/loadtest/education_benefits_claim_1995_stem/README.md

Expected Results

This Jenkins task generates authenticated sessions.

Actual Results

This Jenkins task does not generate authenticated sessions.

Further Details

Add any of the following as available:

From CloudWatchLog Groupsdsva-vagov-staging/srv/vets-api/src/log/vets-api-server.logdeployment-vagov-staging-vets-api-server-20190729-143922-10.247.34.154

{
    "host": "ip-10-247-34-154",
    "application": "vets-api-server",
    "timestamp": "2019-07-30T18:28:06.115227Z",
    "level": "error",
    "level_index": 4,
    "pid": 3088,
    "thread": "puma 003",
    "file": "/srv/vets-api/src/app/controllers/application_controller.rb",
    "line": 74,
    "named_tags": {
        "request_id": "33a1d686-52aa-40c7-81fe-56f61ad98586",
        "remote_ip": "128.229.4.2",
        "user_agent": "python-requests/2.22.0",
        "ref": "d948152bb1ffb61b1d2d769b24480dd87e2da74a"
    },
    "name": "Rails",
    "message": "Not authorized.",
    "payload": {
        "backtrace": [
            "/srv/vets-api/src/app/controllers/concerns/authentication_and_sso_concerns.rb:22:in `render_unauthorized'",
            "/srv/vets-api/src/app/controllers/concerns/authentication_and_sso_concerns.rb:18:in `authenticate'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:426:in `block in make_lambda'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:179:in `block (2 levels) in halting_and_conditional'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:180:in `block in halting_and_conditional'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:513:in `block in invoke_before'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:513:in `each'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:513:in `invoke_before'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:107:in `block in run_callbacks'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/sentry-raven-2.9.0/lib/raven/integrations/rails/controller_transaction.rb:7:in `block in included'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:118:in `instance_exec'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:118:in `block in run_callbacks'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:136:in `run_callbacks'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:41:in `process_action'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_controller/metal/rescue.rb:22:in `process_action'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/notifications.rb:168:in `block in instrument'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/notifications/instrumenter.rb:23:in `instrument'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/notifications.rb:168:in `instrument'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:32:in `process_action'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activerecord-5.2.3/lib/active_record/railties/controller_runtime.rb:24:in `process_action'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/abstract_controller/base.rb:134:in `process'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_controller/metal.rb:191:in `dispatch'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_controller/metal.rb:252:in `dispatch'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/routing/route_set.rb:34:in `serve'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/journey/router.rb:52:in `block in serve'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/journey/router.rb:35:in `each'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/journey/router.rb:35:in `serve'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/routing/route_set.rb:840:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:232:in `context'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:226:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/middleware/cookies.rb:670:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rack-attack-5.0.1/lib/rack/attack.rb:147:in `call'",
            "/srv/vets-api/src/lib/statsd_middleware.rb:13:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/olive_branch-2.0.0/lib/olive_branch/middleware.rb:14:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rack-2.0.7/lib/rack/etag.rb:25:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rack-2.0.7/lib/rack/conditional_get.rb:25:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rack-2.0.7/lib/rack/head.rb:12:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:98:in `run_callbacks'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/middleware/callbacks.rb:26:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rails_semantic_logger-4.4.0/lib/rails_semantic_logger/rack/logger.rb:43:in `call_app'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rails_semantic_logger-4.4.0/lib/rails_semantic_logger/rack/logger.rb:26:in `block in call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/semantic_logger-4.5.0/lib/semantic_logger/semantic_logger.rb:374:in `named_tagged'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/semantic_logger-4.5.0/lib/semantic_logger/base.rb:194:in `tagged'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rails_semantic_logger-4.4.0/lib/rails_semantic_logger/rack/logger.rb:26:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/middleware/request_id.rb:27:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rack-2.0.7/lib/rack/runtime.rb:22:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/activesupport-5.2.3/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/actionpack-5.2.3/lib/action_dispatch/middleware/executor.rb:14:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rack-2.0.7/lib/rack/sendfile.rb:111:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/rack-cors-0.4.1/lib/rack/cors.rb:81:in `call'",
            "/srv/vets-api/src/lib/http_method_not_allowed.rb:16:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/sentry-raven-2.9.0/lib/raven/integrations/rack.rb:51:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/utf8-cleaner-0.2.5/lib/utf8-cleaner/middleware.rb:21:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/railties-5.2.3/lib/rails/engine.rb:524:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/puma-3.12.0/lib/puma/configuration.rb:225:in `call'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/puma-3.12.0/lib/puma/server.rb:658:in `handle_request'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/puma-3.12.0/lib/puma/server.rb:472:in `process_client'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/puma-3.12.0/lib/puma/server.rb:332:in `block in run'",
            "/srv/vets-api/src/vendor/bundle/ruby/2.4/gems/puma-3.12.0/lib/puma/thread_pool.rb:133:in `block in spawn_thread'"
        ]
    }
}

using values from http://jenkins.vfs.va.gov/job/rake_tasks/job/vets-api-load-test-sessions/17/console


[2019-07-30 16:08:18,624] c02wc0jnhtdg.users.bah.com/INFO/locust.main: Run time limit set to 600 seconds
[2019-07-30 16:08:18,624] c02wc0jnhtdg.users.bah.com/INFO/locust.main: Starting Locust 0.11.0
[2019-07-30 16:08:18,626] c02wc0jnhtdg.users.bah.com/INFO/locust.runners: Hatching and swarming 10 clients at the rate 2 clients/s...
[2019-07-30 16:08:23,643] c02wc0jnhtdg.users.bah.com/INFO/locust.runners: All locusts hatched: APIUser: 10
^CTraceback (most recent call last):
  File "./loadtest_runner", line 32, in <module>
[2019-07-30 16:08:30,923] c02wc0jnhtdg.users.bah.com/ERROR/stderr: KeyboardInterrupt
[2019-07-30 16:08:30,923] c02wc0jnhtdg.users.bah.com/ERROR/stderr: 2019-07-30T20:08:30Z
    call(["locust"] + test_args + ["--csv", output])
  File "/usr/local/Cellar/python@2/2.7.16/Frameworks/Python.framework/Versions/2.7/lib/python2.7/subprocess.py", line 172, in call
[2019-07-30 16:08:30,923] c02wc0jnhtdg.users.bah.com/ERROR/stderr:
[2019-07-30 16:08:30,923] c02wc0jnhtdg.users.bah.com/INFO/locust.main: Shutting down (exit code 0), bye.
[2019-07-30 16:08:30,923] c02wc0jnhtdg.users.bah.com/INFO/locust.main: Cleaning up runner...
    return Popen(*popenargs, **kwargs).wait()
  File "/usr/local/Cellar/python@2/2.7.16/Frameworks/Python.framework/Versions/2.7/lib/python2.7/subprocess.py", line 1099, in wait
    pid, sts = _eintr_retry_call(os.waitpid, self.pid, 0)
  File "/usr/local/Cellar/python@2/2.7.16/Frameworks/Python.framework/Versions/2.7/lib/python2.7/subprocess.py", line 125, in _eintr_retry_call
    return func(*args)
KeyboardInterrupt
loadtest$ [2019-07-30 16:08:31,340] c02wc0jnhtdg.users.bah.com/INFO/locust.main: Running teardowns...
 Name                                                          # reqs      # fails     Avg     Min     Max  |  Median   req/s
--------------------------------------------------------------------------------------------------------------------------------------------
 POST /v0/education_benefits_claims/1995                            6     0(0.00%)     188     154     227  |     160    0.50
 GET /v0/in_progress_forms/22-1995                                 14   14(50.00%)     237     122     531  |     130    0.90
--------------------------------------------------------------------------------------------------------------------------------------------
 Total                                                             20   14(70.00%)                                       1.40

Percentage of the requests completed within given times
 Name                                                           # reqs    50%    66%    75%    80%    90%    95%    98%    99%   100%
--------------------------------------------------------------------------------------------------------------------------------------------
 POST /v0/education_benefits_claims/1995                             6    210    210    220    220    230    230    230    230    230
 GET /v0/in_progress_forms/22-1995                                  14    140    400    410    410    410    530    530    530    530
--------------------------------------------------------------------------------------------------------------------------------------------
 Total                                                              20    150    220    400    410    410    530    530    530    530

Error report
 # occurrences      Error
--------------------------------------------------------------------------------------------------------------------------------------------
 14                 GET /v0/in_progress_forms/22-1995: "HTTPError(u'401 Client Error: Unauthorized for url: https://staging-api.va.gov/v0/in_progress_forms/22-1995',)"
--------------------------------------------------------------------------------------------------------------------------------------------```
### Proposed Solution

- *Summary of solution*
- *Link to related tickets*
zurbergram commented 5 years ago

Is the file path at https://github.com/department-of-veterans-affairs/devops/blob/master/ansible/Jenkinsfiles/rake/load_test_sessions#L28 valid ?

zurbergram commented 5 years ago

So it looks like on dev https://github.com/department-of-veterans-affairs/devops/blob/master/ansible/deployment/config/vets-api-server-vagov-dev.yml is missing adding this file But on staging it is adding it https://github.com/department-of-veterans-affairs/devops/blob/master/ansible/deployment/config/vets-api-server-vagov-staging.yml#L149

zurbergram commented 5 years ago

Are the users in https://github.com/department-of-veterans-affairs/devops/blob/master/ansible/deployment/config/vets-api/users_serialized.json all valid ?