Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Idempotency for duplicate quote request #2119

Open
tullon opened this issue Mar 15, 2021 · 17 comments
Open

Idempotency for duplicate quote request #2119

tullon opened this issue Mar 15, 2021 · 17 comments
Labels
blocked bug Something isn't working or it has wrong behavior on a Mojaloop Core service oss-core This is an issue - story or epic related to a feature on a Mojaloop core service or related to it

Comments

@tullon
Copy link

tullon commented Mar 15, 2021

Summary:
When performing transfers between 2 DFSPs through Mowali, the following behavior is observed in Quote request:

  1. Normally a quote request is completed in approximately 2 seconds.
  2. However, if there is a delay in the second leg quote for a forex transfer, Mowali receives a retry of the first leg quote request from payer DFSP.
  3. As per API documentation, this should be neglected via idempotency, where a duplicate request is not acted upon.
  4. However, as per our observation, Mowali does a duplicate check on every quote ID, and if this returns true, sends back an error message to payer DFSP, which then aborts the transfer. But Mowali keeps the quote request alive and pending response from payee DFSP.
  5. In scenario 4 above, if eventually the right response is received from payee DFSP, Mowali will forward this to payer DFSP but the transfer will already have been aborted.

Severity:
Medium

Priority:
Critical

Expected Behavior
A duplicate quote request is supposed to be ignored, as API specs. This will keep the quote alive for payer, payee and hub pending response to the original request. Any error generated terminates the request at one or more actors.

Steps to Reproduce

  1. Send a quote request by Payer DFSP
  2. Delay it's response from switch
  3. Resend the same quote request from Payer DFSP

Specifications

  • Quoting Service:
  • Version: v10.5.1
  • Platform:
  • Subsystem:
  • Type of testing:
  • Bug found/raised by: Mowali TechOps Team

Notes:

  • Severity when opened: High
  • Priority when opened: Critical
@tullon tullon added the bug Something isn't working or it has wrong behavior on a Mojaloop Core service label Mar 15, 2021
@elnyry-sam-k elnyry-sam-k added the oss-core This is an issue - story or epic related to a feature on a Mojaloop core service or related to it label Mar 15, 2021
@elnyry-sam-k
Copy link
Member

@tullon - to confirm, are these two requests exactly the same? If thats the case, the team's initial impression is that there shouldn't be an error message if they're exactly the same.. However, if there's even a minor change, then the error message should be expected (as there's a modification)...

Please confirm and then someone can try to reproduce this...

@tullon
Copy link
Author

tullon commented Mar 16, 2021

@elnyry-sam-k I am going to update with more information that we have got from further testing, which should be more helpful to process the bug.

@elnyry-sam-k
Copy link
Member

Thanks @tullon ..

@tullon
Copy link
Author

tullon commented Mar 17, 2021

Idempotency on Quotes:

We have revisited testing on quotes with the following further notes:
a. We have done testing for both forex and non-forex duplicate quotes.
b. Upon re-evaluation, the error we receive is generated by FXP, and not by core switch quoting service. Below is the flow of both forex and non-forex scenarios:
i. Forex:
Step 1: Payer_DFSP sends 1st quote request
Step 2. Switch processed the request, including duplicate check
Step 3: Switch forwards the quote request to FXP (vDFSP1)
Step 4: FXP (vDFSP2) generates 2nd leg quote to Payee_DFSP via Switch
Step 5: Switch forwards 2nd leg quote to Payee_DFSP

                       ---------- DELAY IN RECEIVING RESPONSE FROM PAYEE DFSP --------------

                 Step 6: Payer_DFSP resends quote request to Switch
                 Step 7: Switch processes the quote request (including duplicate check – which returns true)
                 Step 8: Switch forwards the duplicate quote request to FXP (vDFSP1)
                 Step 9: FXP (vDFSP1) generates an error on this duplicate request and sends back to switch ({\"errorInformation\":{\"errorCode\":\"2001\",\"errorDescription\":\"Internal server error\"}}",)
                Step 10: Switch sends the error back to Payer_DFSP (who then fails that quote request)

------------- At this point, Payer_DFSP has failed that request, but FXP is still waiting for response ------------------------------

              Step 11:  FXP generates a second leg quote time out and sends error to Switch (errorInformation: {errorCode: '2004', errorDescription: 'Second leg of the Request to quote timed out')
              Step 12: Switch sends the second leg time out error to Payer_DFSP

ii. Non-Forex
• After testing with non-Forex, we find that Switch still forwards the same duplicate quote to payee DFSP, which also fails it with the same error status as FXP ({"errorInformation":{"errorCode":"2001","errorDescription":"Internal server error"}}
• In this case, the remote DFSP is behaving exactly the same as the FXP vDFSP in handling the duplicate request.

How does idempotency relate?
i. As per the API spec, the server has only 2 options when it receives a duplicate object:
Option 1: If the unique ID exists and some parameters are different: Raise an error to the payer DFSP
Option 2: If the unique ID and parameter match a previous request: Ignore new request

Expected Behavior:
From the Client / Server idempotency documentation on Mojaloop API Spec, the server should handle idempotency. All this boils down to what product designers meant in this provision:-
a. For transfer, the server is switch, no debate. For quotes, is switch a server, or just a mediator?
b. If we define switch as server, then switch should drop the duplicate request and not forward to remote DFSP
c. If we define the switch as just a middleman, and the payee DFSP as server, then SDK should drop the duplicate request and not raise an error back to switch

@elnyry-sam-k

@elnyry-sam-k
Copy link
Member

elnyry-sam-k commented Mar 19, 2021

Thanks again, for the details @tullon ...

As you rightly pointed out, there are some nuances we need to take into account here. Mojaloop quoting-service is designed to work in two modes: 1) A pass-through mode and 2) A persistent mode (I believe Mowali uses this).

In the pass-through mode, as you pointed out, the Switch is primarily a pass-through service (for quotes) and just mediates the messages based on the headers.

In the persistent mode, it still relies on the FSP (payee FSP) side for most of the decisions (quotes only) but the data is persisted and there are capabilities to apply/enforce rules as configured..

In any case, the API definition terminology of client-server applies to an entity and its neighboring entity, so in this case, (I believe) the Switch is the server, though for any data requirements, it relies on the FSP on the other side for queries or errors, etc.

TL;DR - I think duplicate handling has been designed to work on the quoting-service on both modes and should work.. This seems to be a bug to me. (Also, while noting that the concepts of FXP, vDFSPs are a bit new to the ML open source space.)

@tullon
Copy link
Author

tullon commented Mar 19, 2021

Hi Sam,

We are totally on the same understanding, thank you.

Pardon the infusion of FXP/vDFSP in this scenario, but these just represent the payee DFSP in a forex scenario, as currently implemented by Mowali. So our scenario should not bring any confusion whether Mowali is "talking" to an independent remote payee DFSP, or a virtual DFSP helping to facilitate forex quotes/transfers for a payee DFSP.

Hope this makes sense?

Rgds

@KadidiaN
Copy link

FYI, vDFSP is implemented using the SDK as well as the remote DFSP involved in one of the tests.

@vijayg10 vijayg10 added this to the Sprint 13.5 milestone Mar 30, 2021
@elnyry-sam-k
Copy link
Member

elnyry-sam-k commented Mar 30, 2021

Planning to further investigate this during the current Sprint (13.5)

@elnyry-sam-k elnyry-sam-k removed this from the Sprint 13.5 milestone Apr 14, 2021
@KadidiaN
Copy link

KadidiaN commented May 3, 2021

Hello Sam, @elnyry-sam-k
Any updates on this issues? Thanks

@elnyry-sam-k
Copy link
Member

Hi @KadidiaN , thanks for the reminder, we've prioritized it for this sprint 14.1.. will keep you posted..

@elnyry-sam-k elnyry-sam-k added this to the Sprint 14.1 milestone May 3, 2021
@mdebarros mdebarros self-assigned this May 4, 2021
@mdebarros
Copy link
Member

mdebarros commented May 5, 2021

How Quoting Service handles duplicates

  1. The Quoting Service does NOT handle duplicates in "SIMPLE ROUTING MODE". It will always forward an incoming POST/PUT request/callback as no information is persisted in this mode.

  2. In "PERSISTENT MODE" the following has been observed:

    2.1. When receiving a DUPLICATE POST /quotes request that matches the original request, the Quoting Service will forward the request from the Payer to the Payee without modification. It will do this regardless of the Quote was completed (i.e. received a PUT callback).

    2.2. When receiving a DUPLICATE POST /quotes request that DOES not match the original request, the Quoting Service will respond to the Payer with an Error Callback as follows:

    {
      "method" : "PUT",
      "path" : "/payerfsp/quotes/ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0/error",
      "headers" : {
        "Content-Type" : [ "application/vnd.interoperability.quotes+json;version=1.0" ],
        "Date" : [ "Tue, 04 May 2021 16:42:26 GMT" ],
        "FSPIOP-Source" : [ "switch" ],
        "FSPIOP-Destination" : [ "payerfsp" ],
        "FSPIOP-HTTP-Method" : [ "PUT" ],
        "FSPIOP-URI" : [ "/quotes/ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0/error" ],
        "traceparent" : [ "00-82c04bb480a60a9ac72575815d49b281-973705d6d0cc69ca-00" ],
        "tracestate" : [ "acmevendor=eyJzcGFuSWQiOiI5NzM3MDVkNmQwY2M2OWNhIn0=" ],
        "User-Agent" : [ "axios/0.21.1" ],
        "Content-Length" : [ "161" ],
        "Host" : [ "localhost:1080" ],
        "Connection" : [ "close" ]
      },
      "keepAlive" : false,
      "secure" : false,
      "body" : {
        "type" : "STRING",
        "string" : "{\"errorInformation\":{\"errorCode\":\"3106\",\"errorDescription\":\"Modified request - Quote ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0 is a duplicate but hashes dont match\"}}",
        "contentType" : "application/vnd.interoperability.quotes+json; version=1.0"
      }
    }

    2.3. When receiving a DUPLICATE PUT quotes/{quoteId} callback that matches the original callback, the Quoting Service will forward the callback from the Payee to the Payer without modification.

    2.4. When receiving a DUPLICATE PUT quotes/{quoteId} callback that DOES not match the original callback, the Quoting Service will respond to the Payee with an Error Callback as follows:

    {
      "method" : "PUT",
      "path" : "/payerfsp/quotes/ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0/error",
      "headers" : {
        "Content-Type" : [ "application/vnd.interoperability.quotes+json;version=1.0" ],
        "Date" : [ "Tue, 04 May 2021 16:42:26 GMT" ],
        "FSPIOP-Source" : [ "switch" ],
        "FSPIOP-Destination" : [ "payeefsp" ],
        "FSPIOP-HTTP-Method" : [ "PUT" ],
        "FSPIOP-URI" : [ "/quotes/ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0/error" ],
        "traceparent" : [ "00-82c04bb480a60a9ac72575815d49b281-973705d6d0cc69ca-00" ],
        "tracestate" : [ "acmevendor=eyJzcGFuSWQiOiI5NzM3MDVkNmQwY2M2OWNhIn0=" ],
        "User-Agent" : [ "axios/0.21.1" ],
        "Content-Length" : [ "161" ],
        "Host" : [ "localhost:1080" ],
        "Connection" : [ "close" ]
      },
      "keepAlive" : false,
      "secure" : false,
      "body" : {
        "type" : "STRING",
        "string" : "{\"errorInformation\":{\"errorCode\":\"3106\",\"errorDescription\":\"Modified request - Quote ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0 is a duplicate but hashes dont match\"}}",
        "contentType" : "application/vnd.interoperability.quotes+json; version=1.0"
      }
    }
  3. Quoting Service does not persist "states" as per Mojaloop FSPIOP Specification, section 6.5.6. of a quote, nor does it manage the quote "lifecycle". It only persists the incoming request, incoming callback, and error callback. Thus we can or cannot defer the following:
    3.1. RECEIVED <-- Not possible, as the quoting service does not differentiate from RECEIVED/PENDING states
    3.2. PENDING <-- Could be deferred from a quote record existing in the persistent store
    3.3. ACCEPTED <-- Could be deferred from a quoteResponse record existing in the persistent store
    3.4. REJECTED <-- Could be deferred from a quoteError record existing in the persistent store
    3.5. EXPIRED <-- Not possible. No validations are done for expiration on the PUT /quotes{quoteId}

Analysis

Based on Mojaloop FSPIOP Specification, section 3.2.5.1:


  1. If the previously-created object matches the parameter from the new request, the request should be assumed to be a resend from the client.
    1.1. If the server has not finished processing the old request and therefore has not yet sent the callback to the client, this new request can be ignored, because a callback is about to be sent to the client. <-- Not functioning as per spec on the POST request, the request will be forwarded regardless of the "state" of the Quote.
    1.2. If the server has finished processing the old request and a callback has already been sent, a new callback should be sent to the client, similar to if an HTTP GET request had been sent. <-- Not functioning as per spec on the POST request, and the request is forwarded.
  2. If the previously-created object does not match the parameters from the new request, an error callback should be sent to the client explaining that an object with the provided ID already exists with conflicting parameters. <-- This functionality is as per spec.

Note:
It is also unclear if the above-described functionality was originally intended for the /transfers operations only, as such we need to clarify if this should be applied to all other operations (e.g. /quotes, etc).

Additionally, the use of the term server is also unclear. If the server is considered the "Hub" or "Switch", then the Quoting Service is not functioning as per spec. However, the Quoting Service would function mostly correct if the server is considered the "PayeeFSP" as the "Hub" or "Switch" is merely a Message Router, however, we would expect 2. to be handled by the "PayeeFSP".

I believe the term server should be taken as the "Hub" or "Switch", and that Mojaloop FSPIOP Specification, section 3.2.5.1 should be applied to most FSPIOP operations (e.g. /transfers and /quotes) where the "Hub" or "Switch" needs to validate duplicate requests/callbacks with a backend persistence store.

Recommendation

My recommendation is to change the Quoting Service behaviours to follow Mojaloop FSPIOP Specification, section 3.2.5.1:

a. Ignore DUPLICATE POST /quotes that is in a pending state (i.e. quoting-service has not received a PUT /quotes/{quoteId}).
b. Respond with as a GET /quotes/{quoteId} when receiving DUPLICATE POST /quotes to "PayerFSP" when the quote state is completed (i.e. quoting-service has been processed the associated PUT /quotes/{quoteId}). The GET /quotes/{quoteId} currently only forwards requests, as such it would need to be modified to retrieve the quote response from the persistent store (if it exists - we can assume that the deferred state is "PENDING", and this would only be applicable when "SIMPLE ROUTING MODE" is disabled).
c. Ignore DUPLICATE PUT /quotes/{quoteId} when the quote state is accepted, but log an INTERNAL server error/audit
d. Respond with a PUT /quotes/{quoteId}/error to the "PayerFSP" when the DUPLICATE POST /quotes does not match the original request.

@elnyry-sam-k
Copy link
Member

Thanks Miguel.

The behavior in "simple routing mode" seems fair, since there's no storage of anything.. But we need to look at the persistent mode behavior of forwarding duplicate (resend) requests..

@mdebarros
Copy link
Member

mdebarros commented May 5, 2021

             Step 9: FXP (vDFSP1) generates an error on this duplicate request and sends back to switch ({\"errorInformation\":{\"errorCode\":\"2001\",\"errorDescription\":\"Internal server error\"}}",)

@tullon it's worth mentioning that on Step 9, I believe that the FXP service is not functioning as per Spec. It should also be implementing the same kind of logic as per Mojaloop FSPIOP Specification, section 3.2.5.1. I.e. it should not be responding if the Quote is still in a "PENDING" state as per Mojaloop FSPIOP Specification, section 6.5.6..

I believe that your issue would be fixed if this change was done for the FXP service. This would similarly be applicable for any "FSP" Service receiving a POST /quotes request...i.e. no FSP Service should respond with an error callback if the quote is still "PENDING".

@KadidiaN
Copy link

KadidiaN commented May 5, 2021 via email

@mdebarros
Copy link
Member

mdebarros commented May 6, 2021

In "PERSISTENT MODE" the following has been observed:
2.1. When receiving a DUPLICATE POST request that matches the original request, the Quoting Service will forward the request from the Payer to the Payee without modification. It will do this regardless if the Quote was completed (i.e. received a PUT callback).

This is correct, this how is what I observed when testing the "DUPLICATE" functionality. This will occur for either POST /quotes or PUT /quotes/{quoteId}.

If it forwards to the payee, do you know how is the payee handling?

Step 9: FXP (vDFSP1) generates an error on this duplicate request and sends back to switch ({"errorInformation":{"errorCode":"2001","errorDescription":"Internal server error"}}",)

Yes, refer to Mojaloop FSPIOP Specification, section 3.2.5.1. This describes how a "server" should handle the incoming POST or PUT callbacks, regardless of how the "Quoting Service" itself operators. In my opinion, the "hub" and "PayeeFSP" are "servers" depending on the context....and both should adhere to the functionality described in this section.

I agree , but I think the FXP is implemented using the SDK the same that the simulators are using that's why we wanted to check if the current DFSP participant SDK supports idempotency let's say as a payee for instance.

That is a good question. I only validated the DUPLICATE functionality against the Quoting Service and did not include any FSPs (i.e. simulators) using the SDK.

I will investigate this and provide some feedback.

@mdebarros
Copy link
Member

mdebarros commented May 7, 2021

Confirmed how a DUPLICATE POST /quotes is handled by the SDK Scheme Adapter:

Logs from the Quoting Service receiving a DUPLICATE POST /quotes:

2021-05-07T12:20:09.208Z - �[32minfo�[39m: 2021-05-07T12:20:09.208Z, (1620390009182:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10004) [quotesmodel]: Check duplicate for quoteId 67b91cab-203a-4a81-b5a8-536016d2dd03 returned: { isResend: true, isDuplicateId: true }
2021-05-07T12:20:09.209Z - �[32minfo�[39m: 2021-05-07T12:20:09.209Z, (1620390009182:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10004) [quotesmodel]: Handling resend of quoteRequest: {
  quoteId: '67b91cab-203a-4a81-b5a8-536016d2dd03',
  transactionId: '2cf54810-a720-499e-95a4-26caa7731233',
  payer: {
    partyIdInfo: {
      partyIdType: 'MSISDN',
      partyIdentifier: '44123456789',
      fspId: 'testingtoolkitdfsp'
    },
    personalInfo: { complexName: [Object], dateOfBirth: '1984-01-01' }
  },
  payee: {
    partyIdInfo: {
      partyIdType: 'MSISDN',
      partyIdentifier: '27713803912',
      fspId: 'payeefsp'
    }
  },
  amountType: 'RECEIVE',
  amount: { amount: '100', currency: 'USD' },
  transactionType: {
    scenario: 'TRANSFER',
    initiator: 'PAYER',
    initiatorType: 'CONSUMER'
  },
  note: 'test'
} from testingtoolkitdfsp to payeefsp

Logs showing Quoting Service forwarding the DUPLICATE POST /quotes to the PayeeFSP (SDK-Scheme-Adapter):

2021-05-07T12:20:09.217Z - �[32minfo�[39m: 2021-05-07T12:20:09.217Z, (1620390009182:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10004) [quotesmodel]: Forwarding quote request to endpoint: http://dev2-sim-payeefsp-scheme-adapter:4000/quotes
2021-05-07T12:20:09.218Z - �[32minfo�[39m: 2021-05-07T12:20:09.218Z, (1620390009182:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10004) [quotesmodel]: Forwarding request : {
  method: 'POST',
  url: 'http://dev2-sim-payeefsp-scheme-adapter:4000/quotes',
  data: '{"quoteId":"67b91cab-203a-4a81-b5a8-536016d2dd03","transactionId":"2cf54810-a720-499e-95a4-26caa7731233","payer":{"partyIdInfo":{"partyIdType":"MSISDN","partyIdentifier":"44123456789","fspId":"testingtoolkitdfsp"},"personalInfo":{"complexName":{"firstName":"Firstname-Test","lastName":"Lastname-Test"},"dateOfBirth":"1984-01-01"}},"payee":{"partyIdInfo":{"partyIdType":"MSISDN","partyIdentifier":"27713803912","fspId":"payeefsp"}},"amountType":"RECEIVE","amount":{"amount":"100","currency":"USD"},"transactionType":{"scenario":"TRANSFER","initiator":"PAYER","initiatorType":"CONSUMER"},"note":"test"}',
  headers: {
    'Content-Type': 'application/vnd.interoperability.quotes+json;version=1.0',
    Date: 'Fri, 07 May 2021 12:15:14 GMT',
    'FSPIOP-Source': 'testingtoolkitdfsp',
    'FSPIOP-Destination': 'payeefsp',
    Accept: 'application/vnd.interoperability.quotes+json;version=1.0',
    traceparent: '00-aabb3909fcab3cd8080d37b6b2b65980-48e4ade9b3b222d7-30',
    tracestate: 'mojaloop=eyJzcGFuSWQiOiI0OGU0YWRlOWIzYjIyMmQ3In0='
  }
}

Logs from Quoting services, showing PayeeFSP (SDK-Scheme-Adapter) responding to Quoting Service with a PUT /quotes/{quoteId}/error`:

2021-05-07T12:20:09Z, [log,info] data: got a `PUT /quotes/{id}/error` callback: {
  errorInformation: { errorCode: '2000', errorDescription: 'Generic server error' }
}

Logs from Quoting Service forwarding PUT /quotes/{id}/error callback to PayerFSP (Testing Toolkit):

2021-05-07T12:20:09.335Z - �[32minfo�[39m: 2021-05-07T12:20:09.335Z, (1620390009303:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10005) [quotesmodel]: Making error callback to participant 'testingtoolkitdfsp' for quoteId '67b91cab-203a-4a81-b5a8-536016d2dd03' to http://dev2-ml-testing-toolkit-backend:5000/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error for error: {
  message: 'Generic server error',
  replyTo: undefined,
  apiErrorCode: {
    code: '2000',
    message: 'Generic server error',
    httpStatusCode: 500
  },
  extensions: undefined,
  cause: undefined
}
2021-05-07T12:20:09.356Z - �[32minfo�[39m: 2021-05-07T12:20:09.356Z, (1620390009303:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10005) [quotesmodel]: Error callback got response 200 OK

Here is the log from the SDK-Scheme-Adapter:

{"ts":"2021-05-07T12:20:09.224Z","msg":"Executing HTTP POST","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"},"reqOpts":{"method":"POST","uri":"http://dev2-sim-payeefsp-backend:3000/quoterequests","headers":{"Content-Type":"application/json","Accept":"application/json","Date":"Fri, 07 May 2021 12:20:09 GMT"},"body":"{\"quoteId\":\"67b91cab-203a-4a81-b5a8-536016d2dd03\",\"transactionId\":\"2cf54810-a720-499e-95a4-26caa7731233\",\"to\":{\"idType\":\"MSISDN\",\"idValue\":\"27713803912\"},\"from\":{\"idType\":\"MSISDN\",\"idValue\":\"44123456789\",\"dateOfBirth\":\"1984-01-01\",\"firstName\":\"Firstname-Test\",\"lastName\":\"Lastname-Test\"},\"amountType\":\"RECEIVE\",\"amount\":\"100\",\"currency\":\"USD\",\"transactionType\":\"TRANSFER\",\"initiator\":\"PAYER\",\"initiatorType\":\"CONSUMER\",\"note\":\"test\"}"}}}
{"ts":"2021-05-07T12:20:09.224Z","msg":"Request processed","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"}}}
{"ts":"2021-05-07T12:20:09.225Z","msg":"Cache message received on channel __keyevent@0__:set. Making callback with id 0","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","component":"cache"}}
{"ts":"2021-05-07T12:20:09.225Z","msg":"Received Redis keyevent notification","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-test-api","component":"websocket-server","key":"request_67b91cab-203a-4a81-b5a8-536016d2dd03","channel":"__keyevent@0__:set","id":"0"}}
{"ts":"2021-05-07T12:20:09.271Z","msg":"Error in quoteRequest","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"},"err":"{\"msg\":\"Request returned non-success status code 500\",\"res\":{\"statusCode\":500,\"headers\":{\"content-type\":\"application/json; charset=utf-8\",\"content-length\":\"46\",\"date\":\"Fri, 07 May 2021 12:20:09 GMT\",\"connection\":\"keep-alive\"},\"data\":{\"statusCode\":\"2000\",\"message\":\"Server error\"},\"originalRequest\":{\"method\":\"POST\",\"host\":\"dev2-sim-payeefsp-backend\",\"port\":\"3000\",\"path\":\"/quoterequests\",\"headers\":{\"Content-Type\":\"application/json\",\"Accept\":\"application/json\",\"Date\":\"Fri, 07 May 2021 12:20:09 GMT\",\"content-length\":433},\"agent\":\"[REDACTED]\",\"body\":\"{\\\"quoteId\\\":\\\"67b91cab-203a-4a81-b5a8-536016d2dd03\\\",\\\"transactionId\\\":\\\"2cf54810-a720-499e-95a4-26caa7731233\\\",\\\"to\\\":{\\\"idType\\\":\\\"MSISDN\\\",\\\"idValue\\\":\\\"27713803912\\\"},\\\"from\\\":{\\\"idType\\\":\\\"MSISDN\\\",\\\"idValue\\\":\\\"44123456789\\\",\\\"dateOfBirth\\\":\\\"1984-01-01\\\",\\\"firstName\\\":\\\"Firstname-Test\\\",\\\"lastName\\\":\\\"Lastname-Test\\\"},\\\"amountType\\\":\\\"RECEIVE\\\",\\\"amount\\\":\\\"100\\\",\\\"currency\\\":\\\"USD\\\",\\\"transactionType\\\":\\\"TRANSFER\\\",\\\"initiator\\\":\\\"PAYER\\\",\\\"initiatorType\\\":\\\"CONSUMER\\\",\\\"note\\\":\\\"test\\\"}\"}}}"}}
{"ts":"2021-05-07T12:20:09.272Z","msg":"Sending error response to testingtoolkitdfsp","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"},"mojaloopError":{"errorInformation":{"errorCode":"2000","errorDescription":"Generic server error"}}}}
{"ts":"2021-05-07T12:20:09.272Z","msg":"JWS Signing request: {\n  method: 'PUT',\n  uri: 'http://dev2-quoting-service.mojaloop.live/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error',\n  headers: {\n    'content-type': 'application/vnd.interoperability.quotes+json;version=1.0',\n    date: 'Fri, 07 May 2021 12:20:09 GMT',\n    'fspiop-source': 'payeefsp',\n    'fspiop-destination': 'testingtoolkitdfsp'\n  },\n  body: {\n    errorInformation: { errorCode: '2000', errorDescription: 'Generic server error' }\n  },\n  qs: {},\n  agent: Agent {\n    _events: [Object: null prototype] {\n      free: [Function (anonymous)],\n      newListener: [Function: maybeEnableKeylog]\n    },\n    _eventsCount: 2,\n    _maxListeners: undefined,\n    defaultPort: 80,\n    protocol: 'http:',\n    options: { path: null },\n    requests: {},\n    sockets: {},\n    freeSockets: {},\n    keepAliveMsecs: 1000,\n    keepAlive: false,\n    maxSockets: Infinity,\n    maxFreeSockets: 256,\n    scheduling: 'fifo',\n    maxTotalSockets: Infinity,\n    totalSocketCount: 0,\n    [Symbol(kCapture)]: false\n  }\n}","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"}}}
{"ts":"2021-05-07T12:20:09.272Z","msg":"Get JWS Signature: {\n  method: 'PUT',\n  uri: 'http://dev2-quoting-service.mojaloop.live/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error',\n  headers: {\n    'content-type': 'application/vnd.interoperability.quotes+json;version=1.0',\n    date: 'Fri, 07 May 2021 12:20:09 GMT',\n    'fspiop-source': 'payeefsp',\n    'fspiop-destination': 'testingtoolkitdfsp',\n    'fspiop-http-method': 'PUT',\n    'fspiop-uri': '/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error'\n  },\n  body: {\n    errorInformation: { errorCode: '2000', errorDescription: 'Generic server error' }\n  },\n  qs: {},\n  agent: Agent {\n    _events: [Object: null prototype] {\n      free: [Function (anonymous)],\n      newListener: [Function: maybeEnableKeylog]\n    },\n    _eventsCount: 2,\n    _maxListeners: undefined,\n    defaultPort: 80,\n    protocol: 'http:',\n    options: { path: null },\n    requests: {},\n    sockets: {},\n    freeSockets: {},\n    keepAliveMsecs: 1000,\n    keepAlive: false,\n    maxSockets: Infinity,\n    maxFreeSockets: 256,\n    scheduling: 'fifo',\n    maxTotalSockets: Infinity,\n    totalSocketCount: 0,\n    [Symbol(kCapture)]: false\n  }\n}","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"}}}
{"ts":"2021-05-07T12:20:09.274Z","msg":"Executing HTTP PUT: {\n  reqOpts: {\n    method: 'PUT',\n    uri: 'http://dev2-quoting-service.mojaloop.live/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error',\n    headers: {\n      'content-type': 'application/vnd.interoperability.quotes+json;version=1.0',\n      date: 'Fri, 07 May 2021 12:20:09 GMT',\n      'fspiop-source': 'payeefsp',\n      'fspiop-destination': 'testingtoolkitdfsp',\n      'fspiop-http-method': 'PUT',\n      'fspiop-uri': '/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error',\n      'fspiop-signature': '{\"signature\":\"t0JM_GlAw2WseedgyB_PwgdiFWnrJ3FSzAfiSFe97o1yw4H0Nj1c4MDcBz8YS9OnhL_h1Y5wBU0k7GvXSjI57yj2hEUBDuJf3NTOgQTcSFAfo9GVxAtMyv9tqd-yeh73CxMgrkTqCUUwsaH7nX3-6M24Q5cmTd_gXmZdGujknvlFBWxz-mYFHyyi0Z6xcZFjlMv_Xyq7Rrb5gMIQjnY5pN2jzEExvhAGff7LqN5-L4EvPT-4KHV0gzoCK-ipcmjOPqnzXnnKf9s3vCS4dKn2dL4bp1AcRpWUqXqZ15KnJYMa6MqFV4jubuegip3jYIjVQHc8d9qCUVssJ4hSFrn1hw\",\"protectedHeader\":\"eyJhbGciOiJSUzI1NiIsIkZTUElPUC1VUkkiOiIvcXVvdGVzLzY3YjkxY2FiLTIwM2EtNGE4MS1iNWE4LTUzNjAxNmQyZGQwMy9lcnJvciIsIkZTUElPUC1IVFRQLU1ldGhvZCI6IlBVVCIsIkZTUElPUC1Tb3VyY2UiOiJwYXllZWZzcCIsIkZTUElPUC1EZXN0aW5hdGlvbiI6InRlc3Rpbmd0b29sa2l0ZGZzcCIsIkRhdGUiOiJGcmksIDA3IE1heSAyMDIxIDEyOjIwOjA5IEdNVCJ9\"}'\n    },\n    body: '{\"errorInformation\":{\"errorCode\":\"2000\",\"errorDescription\":\"Generic server error\"}}',\n    qs: {},\n    agent: '[REDACTED]'\n  }\n}","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"}}}
{"ts":"2021-05-07T12:20:09.315Z","msg":"Inbound transfers model handled POST /quotes request","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"},"response":{"originalRequest":{"method":"PUT","host":"dev2-quoting-service.mojaloop.live","port":"","path":"/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error","headers":{"content-type":"application/vnd.interoperability.quotes+json;version=1.0","date":"Fri, 07 May 2021 12:20:09 GMT","fspiop-source":"payeefsp","fspiop-destination":"testingtoolkitdfsp","fspiop-http-method":"PUT","fspiop-uri":"/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error","fspiop-signature":"{\"signature\":\"t0JM_GlAw2WseedgyB_PwgdiFWnrJ3FSzAfiSFe97o1yw4H0Nj1c4MDcBz8YS9OnhL_h1Y5wBU0k7GvXSjI57yj2hEUBDuJf3NTOgQTcSFAfo9GVxAtMyv9tqd-yeh73CxMgrkTqCUUwsaH7nX3-6M24Q5cmTd_gXmZdGujknvlFBWxz-mYFHyyi0Z6xcZFjlMv_Xyq7Rrb5gMIQjnY5pN2jzEExvhAGff7LqN5-L4EvPT-4KHV0gzoCK-ipcmjOPqnzXnnKf9s3vCS4dKn2dL4bp1AcRpWUqXqZ15KnJYMa6MqFV4jubuegip3jYIjVQHc8d9qCUVssJ4hSFrn1hw\",\"protectedHeader\":\"eyJhbGciOiJSUzI1NiIsIkZTUElPUC1VUkkiOiIvcXVvdGVzLzY3YjkxY2FiLTIwM2EtNGE4MS1iNWE4LTUzNjAxNmQyZGQwMy9lcnJvciIsIkZTUElPUC1IVFRQLU1ldGhvZCI6IlBVVCIsIkZTUElPUC1Tb3VyY2UiOiJwYXllZWZzcCIsIkZTUElPUC1EZXN0aW5hdGlvbiI6InRlc3Rpbmd0b29sa2l0ZGZzcCIsIkRhdGUiOiJGcmksIDA3IE1heSAyMDIxIDEyOjIwOjA5IEdNVCJ9\"}","content-length":83},"agent":"[REDACTED]","body":"{\"errorInformation\":{\"errorCode\":\"2000\",\"errorDescription\":\"Generic server error\"}}"}}}}

Log from Mojaloop-Simulator processing DUPLICATE POST /quoterequests:

{
  app: �[32m'simulator'�[39m,
  msg: �[32m'Rule engine evaluating facts: {\n'�[39m +
    �[32m"  path: '/quoterequests',\n"�[39m +
    �[32m'  body: {\n'�[39m +
    �[32m"    quoteId: '67b91cab-203a-4a81-b5a8-536016d2dd03',\n"�[39m +
    �[32m"    transactionId: '2cf54810-a720-499e-95a4-26caa7731233',\n"�[39m +
    �[32m"    to: { idType: 'MSISDN', idValue: '27713803912' },\n"�[39m +
    �[32m'    from: {\n'�[39m +
    �[32m"      idType: 'MSISDN',\n"�[39m +
    �[32m"      idValue: '44123456789',\n"�[39m +
    �[32m"      dateOfBirth: '1984-01-01',\n"�[39m +
    �[32m"      firstName: 'Firstname-Test',\n"�[39m +
    �[32m"      lastName: 'Lastname-Test'\n"�[39m +
    �[32m'    },\n'�[39m +
    �[32m"    amountType: 'RECEIVE',\n"�[39m +
    �[32m"    amount: '100',\n"�[39m +
    �[32m"    currency: 'USD',\n"�[39m +
    �[32m"    transactionType: 'TRANSFER',\n"�[39m +
    �[32m"    initiator: 'PAYER',\n"�[39m +
    �[32m"    initiatorType: 'CONSUMER',\n"�[39m +
    �[32m"    note: 'test'\n"�[39m +
    �[32m'  },\n'�[39m +
    �[32m"  method: 'POST'\n"�[39m +
    �[32m'}'�[39m,
  timestamp: �[32m'2021-05-07T12:20:09.229Z'�[39m
}

Logs from Mojaloop-Simulator showing the POST /quoterequests processing result error: INSERT failure caused by UNIQUE constraint on the quoteId:

{
  app: �[32m'simulator'�[39m,
  request: {
    id: �[32m'cool-church-thinkable-word'�[39m,
    path: �[32m'/quoterequests'�[39m,
    method: �[32m'POST'�[39m
  },
  msg: �[32m'Error in postQuotes: Error: SQLITE_CONSTRAINT: UNIQUE constraint failed: quote.id'�[39m,
  timestamp: �[32m'2021-05-07T12:20:09.270Z'�[39m
}

Additionally looking at the Mojaloop-Simulator code, we can see that there is no "additional" logic to handle duplicate quotes:

From this, we can see that the DUPLICATE POST /quote is being sent by the SDK-Scheme-Adapter to the Mojaloop-Simulator which is then failing to process the request and responding to the SDK-Scheme-Adapter with an error resulting in the POST /quotes/{quoteId}/error callback.

Thus I believe that the issue originating from your FXP Service is NOT generated from the SDK-Scheme-Adapter, but rather the "Backend" implementation.

Please validate this on your side.

Finally, there is a question here to be answered:

Which "FSP" component should be responsible for handling the "DUPLICATE" resend validation...should this be done by the SDK-Scheme-Adapter or the "Backend"?

@elnyry-sam-k
Copy link
Member

Investigation completed, findings documented above and discussed with Mowali team who raised this.

@elnyry-sam-k elnyry-sam-k removed this from the Sprint 14.2 milestone May 31, 2021
@mdebarros mdebarros changed the title Idempotency not working for duplicate quote request Idempotency for duplicate quote request Jul 21, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
blocked bug Something isn't working or it has wrong behavior on a Mojaloop Core service oss-core This is an issue - story or epic related to a feature on a Mojaloop core service or related to it
Projects
None yet
Development

No branches or pull requests

5 participants