App icon indicating copy to clipboard operation
App copied to clipboard

[$250] Another invoice can't be sent after one is paid

Open m-natarajan opened this issue 1 year ago โ€ข 10 comments

If you havenโ€™t already, check out our contributing guidelines for onboarding and email [email protected] to request to join our Slack channel!


Version Number: 9.0.66-0 Reproducible in staging?: y Reproducible in production?: y If this was caught on HybridApp, is this reproducible on New Expensify Standalone?: If this was caught during regression testing, add the test name, ID and link from TestRail: Email or phone of affected tester (no customers): Logs: https://stackoverflow.com/c/expensify/questions/4856 Expensify/Expensify Issue URL: Issue reported by: @neil-marcellini Slack conversation (hyperlinked to channel name): Expensify billpay

Action Performed:

  1. Go to staging.new.expensify.com
  2. Create a workspace if needed
  3. Go to More features, scroll down and enable Invoices
  4. Click green plus, Send invoice
  5. Send an invoice to User B
  6. As User B Go to invoice chat and pay the invoice as business
  7. [User A] Go to invoice report
  8. [User A] Click Add bank account
  9. [User A] In settings Add bank account
  10. Click on the bank account for invoicing and choose to make it the default
  11. Click the green plus, send a $2 to user B
  12. Open the invoice report

Expected Result:

The invoice report can be opened

Actual Result:

The invoice report is not found, because it failed to actually be created even though there was no error message shown in product. The Network response shows 400 Unique Constraints Violation Backlogs : https://www.expensify.com/_devportal/tools/logSearch/#query=request_id:(%228e6c7cac282da4d0-MIA%22)+AND+timestamp:[2024-11-22T21:51:56.285Z+TO+2024-11-22T23:51:56.285Z]&index=logs_expensify-031332

Workaround:

unknown

Platforms:

Which of our officially supported platforms is this issue occurring on?

  • [ ] Android: Standalone
  • [ ] Android: HybridApp
  • [ ] Android: mWeb Chrome
  • [ ] iOS: Standalone
  • [ ] iOS: HybridApp
  • [ ] iOS: mWeb Safari
  • [x] MacOS: Chrome / Safari
  • [ ] MacOS: Desktop

Screenshots/Videos

Add any screenshot/video evidence

https://github.com/user-attachments/assets/11425189-c45d-4c3e-b95a-873ffadb5657

https://github.com/user-attachments/assets/88a5178c-bc2b-46c3-ac90-b5449c2ee59d

View all open jobs on GitHub

Upwork Automation - Do Not Edit
  • Upwork Job URL: https://www.upwork.com/jobs/~021861805315178904377
  • Upwork Job ID: 1861805315178904377
  • Last Price Increase: 2024-12-04
Issue OwnerCurrent Issue Owner: @allgandalf

m-natarajan avatar Nov 23 '24 14:11 m-natarajan

Triggered auto assignment to @zanyrenney (Bug), see https://stackoverflow.com/c/expensify/questions/14418 for more details. Please add this bug to a GH project, as outlined in the SO.

melvin-bot[bot] avatar Nov 23 '24 14:11 melvin-bot[bot]

@zanyrenney Whoops! This issue is 2 days overdue. Let's get this updated quick!

melvin-bot[bot] avatar Nov 27 '24 09:11 melvin-bot[bot]

triaged the bug.

zanyrenney avatar Nov 27 '24 16:11 zanyrenney

Job added to Upwork: https://www.upwork.com/jobs/~021861805315178904377

melvin-bot[bot] avatar Nov 27 '24 16:11 melvin-bot[bot]

Triggered auto assignment to Contributor-plus team member for initial proposal review - @allgandalf (External)

melvin-bot[bot] avatar Nov 27 '24 16:11 melvin-bot[bot]

Waiting for proposals

allgandalf avatar Dec 02 '24 09:12 allgandalf

๐Ÿ“ฃ It's been a week! Do we have any satisfactory proposals yet? Do we need to adjust the bounty for this issue? ๐Ÿ’ธ

melvin-bot[bot] avatar Dec 04 '24 16:12 melvin-bot[bot]

Not sure if this is purely FE, @neil-marcellini can you provide any more data from the logs, can you provide the data received in the logs to see if we send everything correctly ?

allgandalf avatar Dec 05 '24 15:12 allgandalf

Yeah fair, this is probably internal, at least to identify the root cause.

neil-marcellini avatar Dec 05 '24 19:12 neil-marcellini

@neil-marcellini @zanyrenney @allgandalf this issue was created 2 weeks ago. Are we close to a solution? Let's make sure we're treating this as a top priority. Don't hesitate to create a thread in #expensify-open-source to align faster in real time. Thanks!

melvin-bot[bot] avatar Dec 07 '24 10:12 melvin-bot[bot]

@neil-marcellini any updates here ? can you share some logs from devportal ?

allgandalf avatar Dec 11 '24 12:12 allgandalf

It looks like the problem is that we try to create the invoice room report again vs re-using the one that already exists. The invoiceRoomReportID is 1915196797357303 and that's where we get the unique constraints violation. So now it's time to figure out why that happens.

Logs
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 284 [email protected] staging-www1.sjc info Bedrock\Client - Starting a request ~~ command: 'SendInvoice' clusterName: 'auth' headers: '[authToken: '<REDACTED>' senderPolicyID: '65D0DCB20D56CBCD' receiverEmail: '[email protected]' receiverInvoiceRoomID: '0' amount: '200' currency: 'USD' comment: 't2' merchant: '(none)' date: '2024-11-22' category: '' invoiceRoomReportID: '1915196797357303' createdChatReportActionID: '7119337413948476846' invoiceReportID: '8474422852713015' createdIOUReportActionID: '5945907154987080997' reportActionID: '1873530802046189827' reportPreviewReportActionID: '680976267448613529' transactionID: '2148214281977961263' transactionThreadReportID: '4106816954743422' createdReportActionIDForThread: '6699656931864550903' idempotent: '' companyName: '' companyWebsite: '' ip: '104.28.157.233' logParam: '[email protected]' urlToNewDot: 'https://staging.new.expensify.com/' shouldReadUsingThreads: '' shouldHandleOnyxUpdates: '1' isNewDotRequest: '1' clientUpdateID: '3078029124' maxNumberOfUpdates: '500' requestID: '8e6c7cac282da4d0-MIA' lastIP: '104.28.157.233' writeConsistency: 'ASYNC' priority: '500' timeout: '110000']'
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 284 [email protected] staging-www1.sjc info Bedrock\Client - APC fetch host configs ~~ 0: 'db1.sjc' 1: 'db2.sjc' 2: 'db1.lax' 3: 'db2.lax' 4: 'db1.rno' 5: 'db2.rno'
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 284 [email protected] staging-www1.sjc info Bedrock\Client - Possible hosts ~~ nonBlacklistedHosts: '[0: 'db1.sjc' 1: 'db2.sjc' 2: 'db1.rno' 3: 'db2.rno' 4: 'db2.lax' 5: 'db1.lax']'
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 284 [email protected] staging-www1.sjc info Bedrock\Client - Reusing socket ~~ host: 'db1.sjc' cluster: 'auth' pid: '2450273'
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 284 [email protected] db1.sjc info [concurrent] Beginning transaction
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 284 [email protected] db1.sjc info Checking authToken validity for accountID=2777229 / partnerID=83 / partnerUserID=expensify.cash-e000bd93-c3d2-0063-da4e-2e6914511ce7 / isValidated=true / expiresAt=1732322754363771 / isPasswordless=true
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 285 [email protected] db1.sjc info CreateReport::process reportID 1915196797357303
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 285 [email protected] db1.sjc info {SQLITE} Code: 1555, Message: abort at 28 in [INSERT INTO reports ( reportID, created, state, accountID, reportName, currency ) VALUES ( 1915196797357303, '2024-11-22 22:51:56', 0, 0, 'Chat Report', 'USD' );]: UNIQUE constraint failed: reports.reportID
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 285 [email protected] db1.sjc info 'read/write transaction', query failed with error #19 (UNIQUE constraint failed: reports.reportID): INSERT INTO reports ( reportID, created, state, accountID, reportName, currency ) VALUES ( 1915196797357303, '2024-11-22 22:51:56', 0, 0, 'Chat Report', 'USD' );
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 285 [email protected] db1.sjc alrt ENSURE_BUGBOT Encountered random reportID collision! It happened!
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 285 [email protected] db1.sjc warn Unique Constraints Violation, command: SendInvoice
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 285 [email protected] db1.sjc info command 'SendInvoice' timing info (ms): prePeek:0 (count: 0), peek:0 (count:1), process:0 (count:1), postProcess:0 (count:0), total:1, unaccounted:0, blockingCommitThreadTime:0, exclusiveTransactionLockTime:0. Commit: worker:0, sync:0. Queue: worker:0, sync:0, blocking:0, pageLock:0, escalation:0. Blocking: prePeek:0, peek:0, process:0, postProcess:0, commit:0. Upstream: peek:0, process:0, total:0, unaccounted:0.
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 285 [email protected] staging-www1.sjc info Bedrock\Client - Request finished ~~ host: 'db1.sjc' command: 'SendInvoice' jsonCode: '400 Unique Constraints Violation' duration: '2' net: '0.869' wait: '0.331' proc: '0.8' commitCount: ''
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 285 [email protected] staging-www1.sjc info Auth - AuthRequest #2 ~~ command: 'SendInvoice' jsonCode: '400' size: '183' duration: '2ms' host: 'db1.sjc' transactionID: '2148214281977961263'
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 285 [email protected] staging-www1.sjc info Auth - Call SendInvoice return 400
8e6c7cac282da4d0-MIA 2024-11-22 22:51:56 286 [email protected] staging-www1.sjc hmmm Throw ExpException - 20d0858735b59a0bea5fdc18a980d9d0 ~~ message: '400 Unique Constraints Violation' exceptionMessage: 'Auth SendInvoice returned an error' exceptionFile: '/git/releases/expensify.com/535064a/lib/Auth.php' exceptionLine: '133' exceptionCode: '400'

After some digging around I've found that we fail to get the receiverInvoiceRoomID here when sending the invoice. The reason is that we try to get it with receiver type set to individual, but it has been changed to the policy type when the receiver chooses to pay the invoice with a business bank account.

I also noticed that in App that the invoiceReceiver value still has the accountID set within it, but the type is updated to policy. I think maybe the Onyx update doesn't clear the accountID properly, though maybe that's not a big deal.

In Auth we should not be trying the get the invoice room with the receiver type sent to individual when it's been changed to policy, so is App passing the wrong parameters? I see that it's passing the receiverEmail, and in App it looks like it should probably pass the receiverInvoiceRoomID as it would do here if the invoiceChatReport.reportID is set. Evidently it's not.

2024-12-13T16:56:16.463627+00:00 expensidev2004 php-fpm: HOhGcU /api.php [email protected] !ecash9.0.76-0! ?api? [info] Processing 'SendInvoice' for 'expensify.com' from '10.2.2.1'  ~~ command: 'SendInvoice' createdIOUReportActionID: '7853016652172516058' createdReportActionIDForThread: '5342542468315827578' reportActionID: '5442056646700209901' senderWorkspaceID: 'B1E844D99AF93E5C' accountID: '30' amount: '200' currency: 'USD' comment: '' merchant: '(none)' category: '' date: '2024-12-13' invoiceRoomReportID: '6356206350481224' createdChatReportActionID: '1887148289277430468' invoiceReportID: '263505571434242' reportPreviewReportActionID: '7400900744724627612' transactionID: '6793522903945149606' transactionThreadReportID: '2577528467645857' receiverEmail: '[email protected]' pusherSocketID: '810396.164154' authToken: '<REDACTED>' referer: 'ecash' platform: 'web' api_setCookie: 'false' email: '[email protected]' isFromDevEnv: 'true' appversion: '9.0.76-0' clientUpdateID: '1956' partnerName: 'expensify.com' browserGUID: '675c673071051' HTTP_CF_BOT_SCORE: '' HTTP_CF_JA3_HASH: '' HTTP_CF_JA4: ''

If the receiverInvoiceRoomID is set and the receiverEmail is not set, then Auth will hit this block and properly set the invoiceManagerID. Then we won't try and fail to get receiverInvoiceRoomID, nor will we try to create one in these blocks, and so there will be no error and the invoice will be properly created.

So it looks like the next step is to figure out why the invoiceChatReport.reportID is not set in App. I don't like that App has so much control over whether this succeeds in Auth, but I'm not sure there is a way to fix that given the design.

In this flow the user sends the second invoice to the individual (userB) via global create, and it's created as an invoice sent on the chat between userA's workspace and userB's, because userB chose to pay the invoice as a business the first time. That's actually kind of an odd UX, because once userB pays an invoice from you as a business you can't send them an invoice individually. I don't think we should force that. Maybe it's ok if userB can choose to pay it as an individual later, but I'm not sure due to this bug.

Given all that, I will fix it in App for now, then start a discussion about whether we want to change the UX.

neil-marcellini avatar Dec 13 '24 18:12 neil-marcellini

I've been digging into how App behaves, and the first thing I found is that creating another invoice will succeed if the sender signs out and back in, and the Onyx data is refreshed. In that case when you choose the individual from global create, the app will not find an existing invoice chat report between your workspace and the individual, so it will create a new one, pass the optimistic invoiceRoomReportID, and Auth will properly create it. It seems like invoiceChatReport is always undefined in this flow, btw.

It looks like the root cause of the problem is this:

I also noticed that in App that the invoiceReceiver value still has the accountID set within it, but the type is updated to policy.

In that case when getInvoiceChatByParticipants runs it finds an invoice report with data like this. The report shown in the screenshot is the one we're viewing data for, and it's the invoice chat that used to be individual, and is now a policy receiver type.

The key part is that invoiceReceiver.accountID is still set for the individual invoice receiver type. So the function picks this report and will pass it's reportID as the invoiceRoomReportID. Then Auth tries to create a new report with that existing ID, because it can't find the receiverInvoiceRoomID which has an individual receiver type.

image

To fix this, I will have App's getInvoiceChatByParticipants check the receiver type before picking the report. That should be enough, but I'll also make sure the backend clears out the accountID field when the invoice is converted to the policy receiver type.

neil-marcellini avatar Dec 13 '24 20:12 neil-marcellini

The App PR with the fix is ready to go, I just need to write the manual test and record a video.

neil-marcellini avatar Dec 14 '24 03:12 neil-marcellini

@neil-marcellini kudos with the RCA investigation, I was ๐Ÿ˜ฎ reading traces and logs and your explanation !! (Wish i had access to auth repo to look more ๐Ÿ˜ฌ )

allgandalf avatar Dec 15 '24 16:12 allgandalf

PR is ready for review!

neil-marcellini avatar Dec 17 '24 23:12 neil-marcellini

๐Ÿ”ด Hopeful to get the PR merged this week

allgandalf avatar Dec 24 '24 07:12 allgandalf

โ™ป๏ธ PR was merged!!

allgandalf avatar Dec 27 '24 06:12 allgandalf

๐Ÿ”ด PR yet to hit staging

allgandalf avatar Dec 30 '24 19:12 allgandalf

Reviewing label has been removed, please complete the "BugZero Checklist".

melvin-bot[bot] avatar Jan 06 '25 18:01 melvin-bot[bot]

The solution for this issue has been :rocket: deployed to production :rocket: in version 9.0.80-6 and is now subject to a 7-day regression period :calendar:. Here is the list of pull requests that resolve this issue:

  • https://github.com/Expensify/App/pull/54138

If no regressions arise, payment will be issued on 2025-01-13. :confetti_ball:

For reference, here are some details about the assignees on this issue:

  • @allgandalf requires payment (Needs manual offer from BZ)

melvin-bot[bot] avatar Jan 06 '25 18:01 melvin-bot[bot]

@allgandalf @zanyrenney @allgandalf The PR fixing this issue has been merged! The following checklist (instructions) will need to be completed before the issue can be closed. Please copy/paste the BugZero Checklist from here into a new comment on this GH and complete it. If you have the K2 extension, you can simply click: [this button]

melvin-bot[bot] avatar Jan 06 '25 18:01 melvin-bot[bot]

BugZero Checklist:

  • [x] [Contributor] Classify the bug:
Bug classification

Source of bug:

  • [ ] 1a. Result of the original design (eg. a case wasn't considered)
  • [ ] 1b. Mistake during implementation
  • [ ] 1c. Backend bug
  • [x] 1z. Other: There is no source this case was never considered!

Where bug was reported:

  • [x] 2a. Reported on production (eg. bug slipped through the normal regression and PR testing process on staging)
  • [ ] 2b. Reported on staging (eg. found during regression or PR testing)
  • [ ] 2d. Reported on a PR
  • [ ] 2z. Other:

Who reported the bug:

  • [ ] 3a. Expensify user
  • [x] 3b. Expensify employee
  • [ ] 3c. Contributor
  • [ ] 3d. QA
  • [ ] 3z. Other:
  • [x] [Contributor] The offending PR has been commented on, pointing out the bug it caused and why, so the author and reviewers can learn from the mistake.

    Link to comment: N/A (This was never considered, it has been this way since the beginning)

  • [x] [Contributor] If the regression was CRITICAL (e.g. interrupts a core flow) A discussion in #expensify-open-source has been started about whether any other steps should be taken (e.g. updating the PR review checklist) in order to catch this type of bug sooner.

    Link to discussion:

  • [x] [Contributor] If it was decided to create a regression test for the bug, please propose the regression test steps using the template below to ensure the same bug will not reach production again.

  • [ ] [BugZero Assignee] Create a GH issue for creating/updating the regression test once above steps have been agreed upon.

    Link to issue:

Regression Test Proposal

Precondition:

Test:

  1. Create a workspace > Go to More features, scroll down and enable Invoices
  2. Click green plus, Send invoice
  3. Send an invoice to User B
  4. As User B Go to invoice chat and pay the invoice as business
  5. [User A] Go to invoice report
  6. [User A] Click Add bank account
  7. [User A] In settings Add bank account
  8. Click on the bank account for invoicing and choose to make it the default
  9. Click the green plus, send any amount to user B
  10. Open the invoice report and verify it loads successfully

Do we agree ๐Ÿ‘ or ๐Ÿ‘Ž

allgandalf avatar Jan 09 '25 06:01 allgandalf

Payment Summary

Upwork Job

  • ROLE: @allgandalf paid $(AMOUNT) via Upwork (LINK)

BugZero Checklist (@zanyrenney)

  • [ ] I have verified the correct assignees and roles are listed above and updated the neccesary manual offers
  • [ ] I have verified that there are no duplicate or incorrect contracts on Upwork for this job (https://www.upwork.com/ab/applicants/1861805315178904377/hired)
  • [ ] I have paid out the Upwork contracts or cancelled the ones that are incorrect
  • [ ] I have verified the payment summary above is correct

melvin-bot[bot] avatar Jan 13 '25 09:01 melvin-bot[bot]

https://github.com/Expensify/Expensify/issues/459966

zanyrenney avatar Jan 13 '25 19:01 zanyrenney

@allgandalf invited you to the job!

zanyrenney avatar Jan 13 '25 19:01 zanyrenney

https://www.upwork.com/jobs/~021878885655406455636

zanyrenney avatar Jan 13 '25 19:01 zanyrenney

Accepted thanks!!

allgandalf avatar Jan 15 '25 06:01 allgandalf

can you double-check @allgandalf - it doesn't look like you have in upwork. Thanks! normally here we see "view hires" here if the offer has been accepted

Image

zanyrenney avatar Jan 15 '25 18:01 zanyrenney

payment summary

paid $250 to @allgandalf via upwork.

zanyrenney avatar Jan 16 '25 14:01 zanyrenney