LG-9086: Preemptively refresh USPS auth tokens

[sheldon-b]

Note: I suggest starting by disabling whitespace changes when reviewing this PR. A lot of the spec changes were just removing a level of indentation

🎫 Ticket

LG-9086

🛠 Summary of changes

• Fixes a bug where attempting to retrieve a USPS auth token with a memory-backed Rails cache (eg when a dev configures their local environment to communicate with USPS) would fail with an undefined method error
• Changes the USPS preemptive refresh logic to just modify the expires_at cache attribute for the USPS auth token instead of checking when the expiry is within X minutes of expiring
• Reduces the preemptive USPS auth token refresh window from five minutes to one minute. Five minutes seems excessive to me -- that's fully a third of the lifetime of a USPS auth token. The intention of this logic is to prevent in-flight requests from expiring and I think one minute is sufficient for that
• Refactors the proofer specs to rely less on cache implementation details and instead just test that tokens are being refreshed when they should be

📜 Testing Plan

I've tested this feature branch in the Joy sandbox and confirmed that it automatically refreshes the auth token 14 minutes after it was acquired using this procedure:

1. Deploy feature branch to Joy sandbox
2. Open a Rails console
3. Run UspsInPersonProofing::Proofer.new.token, observe that an API request is made (so the cache was cold at this point) and note the time in seconds
4. Wait 13 minutes and re-run UspsInPersonProofing::Proofer.new.token. Confirm no API request is made and it returns the same token as 3.
5. Wait 14 minutes after the initial token and re-run UspsInPersonProofing::Proofer.new.token. Confirm that an API request was made and a new token is returned

You can test this caching locally using these steps:

1. Ensure caching is enabled by running bundle exec rails dev:cache
2. Configure your local environment to make requests to USPS
3. Update your config/application.yml file to define usps_ipp_root_url, usps_ipp_username, usps_ipp_password, usps_ipp_sponsor_id, usps_ipp_client_id, and usps_ipp_mock_fallback: false
4. Restart your web server
5. Start a Rails console. Define a helper function, like so:

6.  def get_token
      puts Time.zone.now
      puts UspsInPersonProofing::Proofer.new.token
    end
   

7. Execute get_token. Observe that an API request is made (it logs a message about posting to the /authenticate endpoint). Note the time, in seconds
8. Wait 10 minutes after the time you noted. Re-run get_token. Observe that no API request is made this time and it prints the same token as before
9. Wait until at least 14 minutes after the time you noted. Re-run get_token and observe that it does make an API request and prints a new token

👀 Demo

irb(main):001:1* def get_token
irb(main):002:1*   puts Time.zone.now
irb(main):003:1*   puts UspsInPersonProofing::Proofer.new.token
irb(main):004:0> end
=> :get_token
irb(main):005:0> get_token
2023-03-22 19:02:39 UTC
{"http_method":"POST","host":"<redacted>","path":"/oauth/authenticate","duration_seconds":0.816173831,"status":200,"service":"usps_token","name":"request_metric.faraday"}
Bearer uqL<redacted>
=> nil
irb(main):055:0> get_token
2023-03-22 19:16:38 UTC
Bearer uqL<redacted>
=> nil
irb(main):056:0> get_token
2023-03-22 19:16:39 UTC
Bearer uqL<redacted>
=> nil
irb(main):057:0> get_token
2023-03-22 19:16:41 UTC
{"http_method":"POST","host":"<redacted>","path":"/oauth/authenticate","duration_seconds":0.653552645,"status":200,"service":"usps_token","name":"request_metric.faraday"}
Bearer kTa<redacted>
=> nil

[mitchellhenke]

I think we may want to use expires_in rather than expires_at?

rails/rails#45047 adds Redis/Memcached support for expires_at, but it hasn't been released yet (I assume it will be in 7.1).

[1] pry(main)> Rails.cache.write('1', '2', expires_in: 10.seconds)
=> "OK"
[2] pry(main)> REDIS_POOL.with { |x| x.ttl('1') }
=> 8
[3] pry(main)> Rails.cache.write('1', '2', expires_at: 10.second.from_now)
=> "OK"
[4] pry(main)> REDIS_POOL.with { |x| x.ttl('1') }
=> -1

[sheldon-b]

Last I checked neither expires_in or expires_at were respected by our redis configuration when using Rails.cache.write. You can see observed behavior in this slack thread. That's why we set the redis ttl just below this, here

[mitchellhenke]

Apologies, I might be misunderstanding, but it looks like expires_in is respected (and expires_at is not for now):

[2] pry(main)> Rails.cache.write('1', '2', expires_in: 10.seconds)
=> "OK"
[3] pry(main)> Rails.cache.redis.ttl('1')
=> 9
[4] pry(main)> REDIS_POOL.with { |x| x.ttl('1') }
=> 9

[sheldon-b]

I tested it out in the Joy environment and it does appear to be working now. I suppose it was fixed or began to be supported in a recent upgrade we did. I'll go ahead and update this PR to remove the redis hack and test it more thoroughly in the Joy sandbox

[sheldon-b]

To be clear I plan to:

1. Update #retrieve_token! to use expires_in instead of expires_at
2. Remove the hacky redis ttl workaround
3. Update specs to not expect the hacky redis ttl workaround
4. Deploy to Joy sandbox and test that caching works as expected

[sheldon-b]

I was able to confirm this change works as expected. For example, here's a demo of it deployed to the Joy sandbox:

irb(main):001:1* def get_token # defining a helper method to print the time and the current token
irb(main):002:1*   puts Time.zone.now
irb(main):003:1*   puts UspsInPersonProofing::Proofer.new.token
irb(main):004:0> end
=> :get_token
irb(main):005:0> get_token # notice here that the cache is cold and so an API request is made to retrieve a token
2023-03-22 19:02:39 UTC
{"http_method":"POST","host":"<redacted>","path":"/oauth/authenticate","duration_seconds":0.816173831,"status":200,"service":"usps_token","name":"request_metric.faraday"}
Bearer uqL<redacted>
=> nil
irb(main):055:0> get_token # notice here that the cache is hot so no API request is made, and the same token is printed
2023-03-22 19:16:38 UTC
Bearer uqL<redacted>
=> nil
irb(main):056:0> get_token
2023-03-22 19:16:39 UTC
Bearer uqL<redacted>
=> nil
irb(main):057:0> get_token # notice here, just over 14 minutes from the last API request, the cache is now cold again and so an API request is made to retrieve a token
2023-03-22 19:16:41 UTC
{"http_method":"POST","host":"<redacted>","path":"/oauth/authenticate","duration_seconds":0.653552645,"status":200,"service":"usps_token","name":"request_metric.faraday"}
Bearer kTa<redacted>
=> nil

I did the same procedure locally with the same results

[eileen-nava]

Hey, everything looks good in the code, but I got a different outcome than expected when I locally tested this.

I

• configured the application.yml to make requests to USPS
• restarted the web server
• started a new rails console (ran bundle exec rails console from the root of identity-idp)
• requested a token
• waited ten minutes to request a token

Then! I received a different token, and the logs led me to believe that a http request occurred. It looks like there was no Rails caching. 😕 Did I miss a step?

[eileen-nava]

👍🏻

[eileen-nava]

Nice use of travel_to.

[sheldon-b]

@eileen-nava hmm I'm not sure. I tried it again and had success locally and in the Joy sandbox, so I suggest one more person verify it works for them and then merge (since you're OOO). I'm interested to pair and look at it though

[NavaTim]

Discussed the caching w/ Sheldon & Mitchell, and it can be enabled for local dev by running rails dev:cache (which creates ./tmp/caching-dev.txt). After that the testing works as expected.

LGTM.

[eileen-nava]

As noted above by Tim, my local testing failed because I didn't have local caching enabled. Here's a helpful slack thread.