View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0007870Talerexchangepublic2023-06-21 12:462023-09-23 15:09
ReporterFlorian Dold Assigned ToChristian Grothoff  
PrioritynormalSeverityminorReproducibilityalways
Status closedResolutionfixed 
Target Version0.9.3Fixed in Version0.9.3 
Summary0007870: long-polling on /kyc-check/ should return early, instead waits for timeout_ms
DescriptionThis happens in the kyc integration test ("taler-harness run-integrationtests kyc").

See relevant logs from the exchange in "Additional Information".

The wallet is making two requests to /kyc-check. The first one returns immediately with 202, indicating that KYC is required.

The wallet then again makes almost the same request, but with timeout_ms=30000.

Then, the test case makes a request to "/kyc-proof" (simulating the user visiting it).

Now, instead of returning from /kyc-check, the exchange waits, until 30 seconds later it decides "Received KYC update event", also it should've received the update earlier! Now "/kyc-check" finally returns, but ~30 seconds too late.
Additional Information2023-06-21T12:32:37.886868+0200 taler-exchange-httpd-151804(0J2BP2J1715V1G8QE35PR33E30) INFO Request for `/kyc-check/1/KKN1QD1C3HHDC0NXRZ1ADY9MX2KB8TNXBTGXCF705GR42W1SS45G/individual' completed with HTTP status 202 (0)
2023-06-21T12:32:37.983149+0200 taler-exchange-httpd-151804(0J2BP2J1715V1G8QE35PR33E30) INFO Handling new request
2023-06-21T12:32:37.983240+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Handling request (GET) for URL '/kyc-check/1/KKN1QD1C3HHDC0NXRZ1ADY9MX2KB8TNXBTGXCF705GR42W1SS45G/individual'
2023-06-21T12:32:37.983262+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Starting DB event listening
2023-06-21T12:32:37.983275+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Executing PQ command `LISTEN XYDWDAZVYT2021PNJ393EJGRA6SBG7E3BFA8CRWWYXNHNA4GXHRHG'
2023-06-21T12:32:37.983446+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Starting transaction `kyc check'
2023-06-21T12:32:37.984053+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Satisfied LEGI check returned 0
2023-06-21T12:32:37.984296+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Initiating KYC check with logic oauth2
2023-06-21T12:32:37.986446+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Suspending HTTP request on KYC logic...
2023-06-21T12:32:37.986523+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO KYC initiation completed with ec=0 (http://localhost:6666/oauth/v2/login?response_type=code&client_id=taler-exchange&redirect_uri=http%3A%2F%2Flocalhost%3A8081%2Fkyc-proof%2FKYC-PROVIDER-MYPROV%3Fstate%3DKKN1QD1C3HHDC0NXRZ1ADY9MX2KB8TNXBTGXCF705GR42W1SS45G)
2023-06-21T12:32:37.987870+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Handling request (GET) for URL '/kyc-check/1/KKN1QD1C3HHDC0NXRZ1ADY9MX2KB8TNXBTGXCF705GR42W1SS45G/individual'
2023-06-21T12:32:37.987897+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Starting transaction `kyc check'
2023-06-21T12:32:37.988974+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Satisfied LEGI check returned 0
2023-06-21T12:32:37.989434+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Suspending HTTP request on timeout (0 ms) now...
2023-06-21T12:32:37.989631+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Handling new request
2023-06-21T12:32:37.989767+0200 taler-exchange-httpd-151804(VGB8Z2CJ6PK7PV6AJ06G90WPKR) INFO Handling request (GET) for URL '/kyc-proof/KYC-PROVIDER-MYPROV'
2023-06-21T12:32:37.993762+0200 taler-exchange-httpd-151804(VGB8Z2CJ6PK7PV6AJ06G90WPKR) INFO HTTP request for `http://localhost:6666/oauth/v2/token' finished with 200 after 2725 µs
2023-06-21T12:32:37.995042+0200 taler-exchange-httpd-151804(VGB8Z2CJ6PK7PV6AJ06G90WPKR) INFO HTTP request for `http://localhost:6666/oauth/v2/info' finished with 200 after 1246 µs
2023-06-21T12:32:37.997121+0200 taler-exchange-httpd-151804(VGB8Z2CJ6PK7PV6AJ06G90WPKR) INFO Trying to start child management.
2023-06-21T12:32:37.997306+0200 taler-exchange-httpd-151804(VGB8Z2CJ6PK7PV6AJ06G90WPKR) INFO Child management started.
2023-06-21T12:32:38.002403+0200 taler-exchange-httpd-151804(VGB8Z2CJ6PK7PV6AJ06G90WPKR) INFO Handling request (GET) for URL '/kyc-proof/KYC-PROVIDER-MYPROV'
2023-06-21T12:32:38.002554+0200 taler-exchange-httpd-151804(VGB8Z2CJ6PK7PV6AJ06G90WPKR) INFO Request for `/kyc-proof/KYC-PROVIDER-MYPROV' completed with HTTP status 303 (0)
2023-06-21T12:33:08.013735+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Received KYC update event
2023-06-21T12:33:08.013871+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Resuming from long-polling on KYC status
2023-06-21T12:33:08.013924+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Handling request (GET) for URL '/kyc-check/1/KKN1QD1C3HHDC0NXRZ1ADY9MX2KB8TNXBTGXCF705GR42W1SS45G/individual'
2023-06-21T12:33:08.013976+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Starting transaction `kyc check'
2023-06-21T12:33:08.015735+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Found satisfied LEGI: KYC-PROVIDER-MYPROV
2023-06-21T12:33:08.015821+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Provider `KYC-PROVIDER-MYPROV' satisfied
2023-06-21T12:33:08.015844+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Provider satisfies check `dummy1'
2023-06-21T12:33:08.015873+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Removing check `dummy1' from list
2023-06-21T12:33:08.015891+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Satisfied LEGI check returned 1
2023-06-21T12:33:08.015907+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO KYC requirements `(null)' already satisfied
2023-06-21T12:33:08.016543+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Cancelling DB event listening
2023-06-21T12:33:08.016624+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Executing PQ command `UNLISTEN XYDWDAZVYT2021PNJ393EJGRA6SBG7E3BFA8CRWWYXNHNA4GXHRHG'
2023-06-21T12:33:08.016904+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Request for `/kyc-check/1/KKN1QD1C3HHDC0NXRZ1ADY9MX2KB8TNXBTGXCF705GR42W1SS45G/individual' completed with HTTP status 202 (0)
2023-06-21T12:33:08.016973+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Request for `/kyc-check/1/KKN1QD1C3HHDC0NXRZ1ADY9MX2KB8TNXBTGXCF705GR42W1SS45G/individual' took 30 s
2023-06-21T12:33:13.110045+0200 taler-exchange-httpd-151804(WBQJRVT4T1BK69YXTQ6TKTSJ40) INFO Handling new request
2023-06-21T12:33:13.110313+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Handling request (GET) for URL '/kyc-check/1/KKN1QD1C3HHDC0NXRZ1ADY9MX2KB8TNXBTGXCF705GR42W1SS45G/individual'
2023-06-21T12:33:13.110403+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Starting DB event listening
2023-06-21T12:33:13.110442+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Executing PQ command `LISTEN XYDWDAZVYT2021PNJ393EJGRA6SBG7E3BFA8CRWWYXNHNA4GXHRHG'
2023-06-21T12:33:13.110778+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Starting transaction `kyc check'
2023-06-21T12:33:13.112257+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Found satisfied LEGI: KYC-PROVIDER-MYPROV
2023-06-21T12:33:13.112328+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Provider `KYC-PROVIDER-MYPROV' satisfied
2023-06-21T12:33:13.112350+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Provider satisfies check `dummy1'
2023-06-21T12:33:13.112367+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Removing check `dummy1' from list
2023-06-21T12:33:13.112383+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Satisfied LEGI check returned 1
2023-06-21T12:33:13.112399+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO KYC requirements `(null)' already satisfied
2023-06-21T12:33:13.112720+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO KYC not required 1
2023-06-21T12:33:13.112876+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Cancelling DB event listening
2023-06-21T12:33:13.112920+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Executing PQ command `UNLISTEN XYDWDAZVYT2021PNJ393EJGRA6SBG7E3BFA8CRWWYXNHNA4GXHRHG'
2023-06-21T12:33:13.113159+0200 taler-exchange-httpd-151804(JFXRRZJ7W0QBW213MPKVCP20CM) INFO Request for `/kyc-check/1/KKN1QD1C3HHDC0NXRZ1ADY9MX2KB8TNXBTGXCF705GR42W1SS45G/individual' completed with HTTP status 204 (0)
TagsNo tags attached.

Activities

Christian Grothoff

2023-06-23 11:43

manager   ~0020300

pg_notify() had to be replaced with 'EXECUTE FORMAT', plus we needed a new GNUnet API to be exposed so that our own process would trigger on our own notifications if those were done inside a stored procedure instead of via the GNUnet PQ notification API. Fun stuff.

Issue History

Date Modified Username Field Change
2023-06-21 12:46 Florian Dold New Issue
2023-06-21 12:46 Florian Dold Status new => assigned
2023-06-21 12:46 Florian Dold Assigned To => Christian Grothoff
2023-06-23 11:43 Christian Grothoff Status assigned => resolved
2023-06-23 11:43 Christian Grothoff Resolution open => fixed
2023-06-23 11:43 Christian Grothoff Fixed in Version => 0.9.3
2023-06-23 11:43 Christian Grothoff Note Added: 0020300
2023-06-23 11:43 Christian Grothoff Target Version 0.9.4 => 0.9.3
2023-09-23 15:09 Christian Grothoff Status resolved => closed