Error message sometimes showing up when searching for an eFolder

[ghost]

Description

After clicking on the Search button from the eFolder Dashboard, an error message is received.
However, if I go back to the Dashboard history and then to View Progress for that eFolder, it shows that documents were, in fact, listed.

This might be a network issue of some sort; but I was able to isolate it to the original query sent by the Search button. For whatever reason, listDocument or another command return errors despite the query actually going through.

Environment:

• Production
• UAT
• Demo
• Development

Type of Bug:

• Performance
• Design
• Security
• Functional

Severity Level:

• 5 - Data loss, data corruption or system unavailable
• 4 - Important functionality is unavailable with no workaround
• 3 - Important functionality is unavailable but has a reasonable workaround
• 2 - Secondary functionality is unavailable but has a reasonable workaround
• 1 - Cosmetic issues or some functionality unavailable but has a simple workaround

Reproductive Steps

Scenario 1 - Start retrieving eFolder button

1. Go to eFolder
2. Enter a value in the Search field.
3. Click on the Search button.
4. Get Uh Oh message. (maybe)
5. Click on the search again link in the Uh Oh Error page. The 'Dashboard` page is displayed.
6. Enter another Veteran ID to search for and click Search button. The Manifest page is displayed with files listed.
7. Click on the Start retrieving eFolder button.
8. Get Uh Oh message is received.
9. Click on the search again link in the Uh Oh Error page. The 'Dashboard` page is displayed.
   With the previous items in History. If not, click search again for that same Veteran ID and repeat steps.

Screenshots

Scenario 1 - Error Message

Related Issues

Support Tickets
Dashboard | Start retrieving eFolder | Error message displayed - uh oh #60
Engineering Issues
Efolder client side polling is too aggressive, and leads to HTTP backup. #373
Document counts inaccurate on redownload - #353

[amprokop]

@kierachell — this may have been fixed by #403, which is now merged. Can you lmk if you see this again?

[ghost]

@nemodjuric
The error now shows up in demo upon searching for any new Download:

)  COMMIT
dsva-appeals-efolder-dev /opt/efolder-express/src/log/efolder-express.out [dsva-appeals-efolder-dev-972029178.us-gov-west-1.elb.amazonaws.com] [dec0bdf6-7fe5-4474-9501-1f2dffddbfdd] [localhost] [CSFLOW0 CASEFLOW1] [2017-04-01 08:23:49 -0400]   Download Load (1.2ms)  SELECT  "downloads".* FROM "downloads" WHERE ("downloads"."created_at" BETWEEN '2017-03-29 12:23:49.066131' AND '2017-04-01 12:23:49.066152') AND "downloads"."user_id" = 8 AND "downloads"."id" = $1 LIMIT 1  [["id", 191]]
dsva-appeals-efolder-dev /opt/efolder-express/src/log/efolder-express.out [dsva-appeals-efolder-dev-972029178.us-gov-west-1.elb.amazonaws.com] [dec0bdf6-7fe5-4474-9501-1f2dffddbfdd] [localhost] [CSFLOW0 CASEFLOW1] [2017-04-01 08:23:49 -0400] Record not found... Exception ActiveRecord::RecordNotFound: Couldn't find Download with 'id'=191 [WHERE ("downloads"."created_at" BETWEEN '2017-03-29 12:23:49.066131' AND '2017-04-01 12:23:49.066152') AND "downloads"."user_id" = 8]
dsva-appeals-efolder-dev /opt/efolder-express/src/log/efolder-express.out [dsva-appeals-efolder-dev-972029178.us-gov-west-1.elb.amazonaws.com] [dec0bdf6-7fe5-4474-9501-1f2dffddbfdd] [localhost] [CSFLOW0 CASEFLOW1] [2017-04-01 08:23:49 -0400]   Rendered downloads/not_found.html.erb within layouts/application (0.1ms)

The log above is the error on initial attempt to ListDocuments. The website renders Uh Oh message even though the job to retrieve the manifest still goes through. So, reattempting to list the documents will result in normal behavior.

Steps to reproduce:

1. Go to eFolder

2. Search for a file that you have not searched for in the past 3 days

3. Get Uh Oh message, and see the error log above

4. Go back a page and search again

5. See that the request was actually sent and processed

[amprokop]

@kierachell — did we have any other issues causing this bug?

[nikitarockz]

@kierachell @sharonwarner Is this still an open issue? I ask this because it is tied to a support issue. As long as this is open, so is the support issue. Support issues are being tracked by how long they remain open.

[ghost]

@nikitarockz @aroltsch

Still happening:

[anyakhvost]

Unfortunately, my current fix didn't solve the issue :(. The problem is the following:

1. It first looks for a download, doesn't find it. Look in match_existing_download code
2. Inserts the download
3. Starts the job
   I thought the problem was between steps 2 and 3 but it might be between steps 1 and 2.
   I will keep debugging.

[anyakhvost]

More debugging into this:
Download.active uses where(created_at: Download::HOURS_UNTIL_EXPIRY.hours.ago..Time.zone.now

Couldn't find Download with 'id'=265 [WHERE ("downloads"."created_at" BETWEEN '2017-06-17 12:32:18.319493' AND '2017-06-20 12:32:18.319514') AND "downloads"."user_id" = 17] 

But the insert happens a few seconds later!

[2017-06-20 12:32:19 +0000]   SQL (1.1ms)  INSERT INTO "downloads" ("file_number", "user_id", "created_at", "updated_at", "veteran_first_name", "veteran_last_name", "veteran_last_four_ssn", "lock_version") VALUES ($1, $2, $3, $4, $5, $6, $7, $8) RETURNING "id"  [["file_number", "314531812"], ["user_id", 17], ["created_at", "2017-06-20 12:32:18.807388"], ["updated_at", "2017-06-20 12:32:18.807388"], ["veteran_first_name", "MXRIETTA"], ["veteran_last_name", "JOANNA"], ["veteran_last_four_ssn", "1812"], ["lock_version", 0]]

[ghost]

PASSED

Ran about 500 file numbers in UAT. No Uh Ohs

💯