Tracking View Payments / Ch33 Performance Issue

[RudyOnRails]

Background

This ticket Epic's purpose is to document what happened, develop questions to ask or unknowns to know, and store any research and/or evidence to support decisions going forward.

TL;DR

The Ch33 direct deposit endpoint and the payment information endpoint have both been down/mostly down for a similar period of time (since Wednesday, Dec 8) and are both supported by the same backend system -- BGS.

Ch33

December 1, Samara noticed an issue on prod and asked if someone could check the Profile in prod issue was very sporadic and could not be reproduced in lower environments or locally. Occasionally it would fail to load all profile information and this alert would be displayed:


December 8, Lihan contacted BGS via email to inquire about DDEFT latency. We received no answers that day, but they did loop in other teams (Team 1, WebLogic Admin)

December 9, Cory Easley looped in Tuxedo team around 7:30 AM ET. We got a response back from Vehkaiah Kolla at around 10:15 AM ET saying the Tuxedo and Bull admins did not notice any slowdowns. A joint call was set up at 12:30 PM ET and most of the afternoon was spent with Lihan Li, Joe Niquette, Lance Sanchez, Boris Ning comparing logs and request/response times with BGS. During some of the calls, the fwd proxy would occasionally fail to connect. We looped in the Ops team (Bill Ryan) for additional support

Dec 10 - 13, Lance Sanchez, Boris Ning, Mike Chelen continued to troubleshoot. Demian Ginther concluded that VA Network may need to be looped in since Ops has not visibility once it leaves the forward proxy.

Dec 14

• Marci requested a VA Networking contact from Demian and was referred to Boris Ning.
• Boris advised that we probably did not have sufficient data for looping in VA Network just yet, and that we would need to have more logging and debugging.
• Joe also identified a CORS issue that day, which Lance investigated, and noted that sometimes takes 10-20 seconds to establish a connection to BG.S, but that delay could not be replicated with curl on the TIC Gateway West - only took 1-2 sec.

Dec 15

• Joe posted testing results so far...largely a mixed bag, only consistent thing is called the curl soapaction to bgs from vets-api prod works every time. All other methods pass and fail at random
• Samara noted that OCTO is getting reports that payment history isn't loading, and BGS also manages that. Chris Johnston reached out to the product line manager at VBA in order to try to escalate the issue.

Dec 16

• CORS problem not yet fixed, but Joe advised they are more confident that it's only an issue on the return of an error
• Boris advised that it looked to him like it was indicative of vets-api not responding, but also said that there were specific calls with high latency, and it was probably not network
• Boris also advised that another interesting traffic pattern is the public -> vets-api, which traverses through the TIC gateway to get to vets-api.
• We had another joint call with BGS from 11:30 AM ET - 1:00 PM ET in which requests were sent and BGS watched for responses and shared logs.
• Joe advised CORS issue is ruled out because they see delays when not going through a browser.
• Boris advised fwd proxy is likely ruled out based on data Bill captured. and Joe also concurred saying it was ruled out by confirming that BGS receives the request in all testing paths immediately. https://dsva.slack.com/archives/C02Q9FL124F/p1639513906054600?thread_ts=1639512795.049100&cid=C02Q9FL124F
• code is ruled out because we made the calls directly from vets-api controllers to BGS, all returned with no issues
• What's left to investigate is puma and reverse proxy. Puma is part of the response.

View Payments

On Wed, Dec 15, Jason was informed that view-payments was lagging/down for the past few days.

Context

• Debugging channel: https://dsva.slack.com/archives/C02Q9FL124F/p1639500862000200

Affected Features (in order of appearance)

• Chapter 31 (VR&E 1900) - Issue began in October - ORIGINAL TICKET:
  • @service.people.find_person_by_ptcpnt_id(@user.participant_id, @user.ssn)
  • workaround was to move the lengthy work into a job so that it wouldn't time out on the FE
• Chapter 33 (Direct Deposit for EDU)
  • service.claims.send(:request, :find_ch33_dd_eft, fileNumber: @user.ssn)
  • service.ddeft.find_bank_name_by_routng_trnsit_nbr(routing_number)
  • ch33_bank_accounts
  • workaround was to modify the code so that loading the VA.gov profile did not depend on retrieving Ch 33 data
• View Payments
  • person = BGS::PeopleService.new(current_user).find_person_by_participant_id
  • response = BGS::PaymentService.new(current_user).payment_history(person)
• Profile was loading Ch33 items as well; resulting with an error info cannot be retrieved
• !Screenshot-coming-soon

Findings

• Joe N found on logging into prod he found response times as being long (69+s)
• First call is successful because the next call can't happen unless that happens
• Forward proxy was ruled out
• BGS seems to maintains that they are seeing no lags or latency issues
• Google Analytics did not seem to show a rising number of failures

Hypotheses #

ID	Hypothesis	Support	Determination
1	The issue only occurs during weekdays and not on weekends	Oct 30th was a Sat	False
2	The issue became significantly worse after 12/9	Here is the issues days earlier	False
3	Logging	SemanticLogger is showing signs of (at times hundreds of thousands) logs being queued up	Checking results of this PR

Next Steps / Tasks

• [x] Call with BGS; seemed that they needed more evidence to point to where the issue lived [Marci]
• [x] Joe N. is seeking more error handling and logs to help determine where exactly all the time is being spent

Results

-

Acceptance Criteria

• [x] The issue has had a path forward determined
• [x] The issue has been addressed
• [x] A PR has been requested for merging, if needed and/or applicable

[drorva]

Office hours with ops meeting 12/17

• VSP ops will increase resources for Loki since we're currently losing some log data
• Next time we see the issue of response time climbing ops will change the error level from INFO to ERROR
• We're creating a datadog alert to notify us when we see the issue of response time being slow and errors showing

[mchelen-gov]

@drorva Thanks for the update! Is there a GH issue for the DD alert creation?

[RudyOnRails]

@drorva Thanks for the update! Is there a GH issue for the DD alert creation?

@mchelen-gov actually there is not, good question. I am working on perfecting the monitor now, but will create an issue now.