View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0008225Talermechant backendpublic2024-01-23 17:542024-03-07 20:47
Reporterdvn Assigned ToChristian Grothoff  
PrioritynormalSeveritymajorReproducibilityalways
Status closedResolutionreopened 
Target Version0.9.4Fixed in Version0.9.4 
Summary0008225: Merchant Testsuite Failing
DescriptionMerchant is failing its testsuite.

See: https://buildbot.taler.net/#/builders/16/builds/344
Steps To ReproduceRun `./contrib/ci/ci.sh 2-test` from root of merchant.git
TagsNo tags attached.

Relationships

related to 0008148 closeddvn Merchant CI environment missing taler-harness 
child of 0008153 closedChristian Grothoff test, package and upload merchant 0.9.4 to ftp and stable Debian/Ubuntu server 

Activities

oec

2024-01-23 18:02

developer   ~0020997

============================================================================
Testsuite summary for taler-merchant 0.9.4
============================================================================
# TOTAL: 15
# PASS: 10
# SKIP: 1
# XFAIL: 0
# FAIL: 4
# XPASS: 0
# ERROR: 0
============================================================================
See src/testing/test-suite.log
Please report to taler-bug@gnunet.org
============================================================================
make[4]: *** [Makefile:1245: test-suite.log] Error 1
make[4]: Leaving directory '/workdir/src/testing'
make[3]: *** [Makefile:1353: check-TESTS] Error 2
make[3]: Leaving directory '/workdir/src/testing'
make[2]: *** [Makefile:1538: check-am] Error 2
make[2]: Leaving directory '/workdir/src/testing'
make[1]: *** [Makefile:410: check-recursive] Error 1
make[1]: Leaving directory '/workdir/src'
make: *** [Makefile:470: check-recursive] Error 1
Printing test_merchant_api_cs.log
>>(null)<<
2024-01-23T16:33:15.747622+0000 /workdir/src/testing/.libs/test_merchant_api_cs-5113 ERROR Failed at command `orders-id'
2024-01-23T16:33:15.747686+0000 /workdir/src/testing/.libs/test_merchant_api_cs-5113 ERROR Batch is at command `instance-create-default'
2024-01-23T16:33:15.747751+0000 /workdir/src/testing/.libs/test_merchant_api_cs-5113 ERROR Failed at command `orders-id'
2024-01-23T16:33:15.747804+0000 /workdir/src/testing/.libs/test_merchant_api_cs-5113 ERROR Batch is at command `instance-create-default'
2024-01-23T16:33:15.747865+0000 /workdir/src/testing/.libs/test_merchant_api_cs-5113 INFO HTTP request for `' finished with 0 after 12 µs
2024-01-23T16:33:15.747943+0000 /workdir/src/testing/.libs/test_merchant_api_cs-5113 INFO Executing shutdown at `orders-id'
2024-01-23T16:33:15.750312+0000 /workdir/src/testing/.libs/test_merchant_api_cs-5113 INFO Child management stopped.
Taler unified setup terminating!
FAIL test_merchant_api_cs (exit status: 1)
Printing test_merchant_api_rsa.log
>>(null)<<
2024-01-23T16:33:26.233873+0000 /workdir/src/testing/.libs/test_merchant_api_rsa-5336 ERROR Failed at command `orders-id'
2024-01-23T16:33:26.234002+0000 /workdir/src/testing/.libs/test_merchant_api_rsa-5336 ERROR Batch is at command `instance-create-default'
2024-01-23T16:33:26.234066+0000 /workdir/src/testing/.libs/test_merchant_api_rsa-5336 ERROR Failed at command `orders-id'
2024-01-23T16:33:26.234127+0000 /workdir/src/testing/.libs/test_merchant_api_rsa-5336 ERROR Batch is at command `instance-create-default'
2024-01-23T16:33:26.234195+0000 /workdir/src/testing/.libs/test_merchant_api_rsa-5336 INFO HTTP request for `' finished with 0 after 11 µs
2024-01-23T16:33:26.234264+0000 /workdir/src/testing/.libs/test_merchant_api_rsa-5336 INFO Executing shutdown at `orders-id'
2024-01-23T16:33:26.236502+0000 /workdir/src/testing/.libs/test_merchant_api_rsa-5336 INFO Child management stopped.
Taler unified setup terminating!
FAIL test_merchant_api_rsa (exit status: 1)
Printing test_kyc_api.log
2024-01-23T16:33:37.045461+0000 /workdir/src/testing/.libs/test_kyc_api-5564 ERROR Unexpected response code 0 (expected: 204) to command instance-create-default-setup in testing_api_cmd_post_instances.c:115
with body:
>>(null)<<
2024-01-23T16:33:37.045590+0000 /workdir/src/testing/.libs/test_kyc_api-5564 ERROR Failed at command `instance-create-default-setup'
2024-01-23T16:33:37.045721+0000 /workdir/src/testing/.libs/test_kyc_api-5564 ERROR Failed at command `instance-create-default-setup'
2024-01-23T16:33:37.045863+0000 /workdir/src/testing/.libs/test_kyc_api-5564 INFO HTTP request for `' finished with 0 after 13 µs
2024-01-23T16:33:37.046001+0000 /workdir/src/testing/.libs/test_kyc_api-5564 INFO Executing shutdown at `instance-create-default-setup'
2024-01-23T16:33:37.048235+0000 /workdir/src/testing/.libs/test_kyc_api-5564 INFO Child management stopped.
Taler unified setup terminating!
FAIL test_kyc_api (exit status: 1)
Printing test_merchant_wirewatch.sh.log
Pay first order ...OK. Took 1s.
Perform wire transfers (with 50s timeshift) ... DONE
Obtaining wire transfer details from bank... OK
Fetching wire transfers of DEFAULT instance ...Expected one transfer. Got: 0 {
  "transfers": []
}
Killing taler-unified-setup (8640)
Taler unified setup terminating!
Terminated
FAIL test_merchant_wirewatch.sh (exit status: 1)
program finished with exit code 1

oec

2024-01-24 11:50

developer   ~0021018

This is a weird problem. Take `test_merchant_api_cs`: it fails as described above, with HTTP requests return 0, hinting that the merchant httpd did not start properly.

However, when I start the test manually in the container, stop the test halfway, I can see the merchant-httpd being started:

```
root@32e5946618d3:/workdir/src/testing# ./test_merchant_api_cs
2024-01-24T10:41:14.070344+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Running command `run-fakebank'
Warning: "1", specified for thread pool size, is ignored. Thread pool is not used.
2024-01-24T10:41:14.070981+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Running command `start-taler'
2024-01-24T10:41:14.073168+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Trying to start child management.
2024-01-24T10:41:14.073338+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Child management started.
2024-01-24 10:41:14.486 UTC [38342] root@talercheck ERROR: unrecognized configuration parameter "autocommit"
2024-01-24 10:41:14.486 UTC [38342] root@talercheck STATEMENT: SET autocommit=OFF;
2024-01-24 10:41:15.367 UTC [38402] root@talercheck ERROR: unrecognized configuration parameter "autocommit"
2024-01-24 10:41:15.367 UTC [38402] root@talercheck STATEMENT: SET autocommit=OFF;
2024-01-24 10:41:36.394 UTC [38459] root@talercheck ERROR: unrecognized configuration parameter "autocommit"
2024-01-24 10:41:36.394 UTC [38459] root@talercheck STATEMENT: SET autocommit=OFF;
^Z
[1]+ Stopped ./test_merchant_api_cs
root@32e5946618d3:/workdir/src/testing# netstat -tlpn
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
tcp 0 0 127.0.0.1:5432 0.0.0.0:* LISTEN 16340/postgres
tcp6 0 0 :::8082 :::* LISTEN 38281/test_merchant
tcp6 0 0 :::8083 :::* LISTEN 38456/taler-auditor
tcp6 0 0 :::8080 :::* LISTEN 38425/taler-merchan
tcp6 0 0 :::8081 :::* LISTEN 38356/taler-exchang
```

When I `kill -CONT` the merchant, I can manually configure an instance on the merchant:

```
root@32e5946618d3:/workdir/src/testing# kill -CONT 38425
root@32e5946618d3:/workdir/src/testing# curl http://localhost:8080/management/instances
{
  "instances": []
root@32e5946618d3:/workdir/src/testing# curl -H "Content-Type: application/json" -X POST -H 'Authorization: Bearer secret-token:super_secret' http://localhost:8080/management/instances -d '{"auth":{"method":"external"},"id":"default","name":"default","user_type":"business","address":{},"jurisdiction":{},"use_stefan":true,"default_wire_transfer_delay":{"d_us" : 50000000},"default_pay_delay":{"d_us": 60000000}}' -w "%{http_code}" -s
root@32e5946618d3:/workdir/src/testing#
root@32e5946618d3:/workdir/src/testing# curl http://localhost:8080/management/instances
{
  "instances": [
    {
      "name": "default",
      "user_type": "business",
      "id": "default",
      "merchant_pub": "YCZB02437KNZX3QBEX50Q428X181XW8GZP9ARRE6WDESBT85MH6G",
      "payment_targets": [],
      "deleted": false
    }
  ]
}
```

Yet, continuing the test fails:

```
root@32e5946618d3:/workdir/src/testing# fg
./test_merchant_api_cs
2024-01-24T10:42:29.377318+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Taler system UP
2024-01-24T10:42:29.377413+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Running command `get-exchange'
* Trying 127.0.0.1:8081...
* Connected to localhost (127.0.0.1) port 8081 (#0)
> GET /keys HTTP/1.1
Host: localhost:8081
Accept: */*
Accept-Encoding: deflate, gzip, br, zstd
Content-Type: application/json

< HTTP/1.1 200 OK
< Date: Wed, 24 Jan 2024 10:42:29 GMT
< Connection: close
< Content-Encoding: deflate
< Access-Control-Allow-Origin: *
< Access-Control-Expose-Headers: *
< Content-Type: application/json
< Last-Modified: Wed, 24 Jan 2024 10:42:28 GMT
< Expires: Wed, 31 Jan 2024 10:42:28 GMT
2024-01-24T10:42:29.382465+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Found Expires header `Wed, 31 Jan 2024 10:42:28 GMT
'
< Vary: Accept-Encoding
< Cache-Control: public,max-age=3600
< Vary: Accept-Encoding
< Cache-Control: public,max-age=86400
< ETag: 1045TXPSQRWAMF1MFW2TRHCMJMFKYVEJ4HTA8X0J6AW3GHQ302DGHG4C8H17PHEYXCC0JY60V2HQZ0HKETX05JTRBZYEZ53XCAXHSFR
< Content-Length: 27296
<
* Closing connection 0
2024-01-24T10:42:29.390452+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Received keys from URL `http://localhost:8081/keys' with status 200 and expiration Wed Jan 31 10:42:28 2024.
2024-01-24T10:42:29.392632+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Parsed 1 wire accounts from JSON
2024-01-24T10:42:29.465950+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO HTTP request for `http://localhost:8081/keys' finished with 200 after 6 ms
2024-01-24T10:42:29.466033+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Running command `orders-id'
2024-01-24T10:42:29.466049+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Running batched command: instance-create-default
2024-01-24T10:42:29.466112+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO XXXXXXXXX calling http://localhost:8080/management/instances
2024-01-24T10:42:29.466819+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO POST /management/instances completed with response code 0
2024-01-24T10:42:29.466853+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 ERROR Unexpected response code 0 (expected: 204) to command orders-id in testing_api_cmd_post_instances.c:115
with body:
>>(null)<<
2024-01-24T10:42:29.466873+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 ERROR Failed at command `orders-id'
2024-01-24T10:42:29.466892+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 ERROR Batch is at command `instance-create-default'
2024-01-24T10:42:29.466911+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 ERROR Failed at command `orders-id'
2024-01-24T10:42:29.466925+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 ERROR Batch is at command `instance-create-default'
2024-01-24T10:42:29.466946+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO HTTP request for `' finished with 0 after 24 µs
2024-01-24T10:42:29.466965+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Executing shutdown at `orders-id'
2024-01-24T10:42:29.469534+0000 /workdir/src/testing/.libs/test_merchant_api_cs-38281 INFO Child management stopped.
Taler unified setup terminating!
```

Somehow, the testing API doesn't seem to connect to the merchant, even though the URL is correct.

oec

2024-01-24 11:51

developer   ~0021019

Please have a look at my last note. Any ideas?

oec

2024-01-30 13:46

developer   ~0021091

Turns out that the root-cause was an inconsistency between the usage of `libcurl4-gnutls` in all debian packages installed for gnunet and taler, but the usage of `libcurl4-openssl-dev` for this container. Unfortunately, libcurl doesn't give us a clear hint of what the issue actually is, it simply complains with `No URL set!` (with CURLOPT_VERBOSE on).

Commit 88e15ec1228d46e8eb5f430fc8c2070796e32f13 substitutes `libcurl4-openssl-dev` for `libcurl4-gnutls-dev` and the previously failing tests pass now. (There is another test failing right now, but this is due to some other issue).

oec

2024-01-30 14:06

developer   ~0021093

Now only test `test_kyc_api` fails:

```
2024-01-30T12:56:36.881965+0000 /workdir/src/testing/.libs/test_kyc_api-17359 INFO Running command `pay'
2024-01-30T12:56:36.881980+0000 /workdir/src/testing/.libs/test_kyc_api-17359 INFO Running batched command: kyc-pending
2024-01-30T12:56:36.983775+0000 /workdir/src/testing/.libs/test_kyc_api-17359 INFO HTTP request for `http://localhost:8080/private/kyc?exchange_url=http%3A%2F%2Flocalhost%3A8081%2F' finished with 202 after 101 ms
2024-01-30T12:56:36.983834+0000 /workdir/src/testing/.libs/test_kyc_api-17359 INFO Running command `pay'
2024-01-30T12:56:36.983852+0000 /workdir/src/testing/.libs/test_kyc_api-17359 INFO Running batched command: kyc-do
2024-01-30T13:01:29.159203+0000 /workdir/src/testing/.libs/test_kyc_api-17359 ERROR Terminating test due to timeout
2024-01-30T13:01:29.159340+0000 /workdir/src/testing/.libs/test_kyc_api-17359 INFO Executing shutdown at `pay'
2024-01-30T13:01:29.162517+0000 /workdir/src/testing/.libs/test_kyc_api-17359 INFO Child management stopped.
Taler unified setup terminating!
2024-01-30T13:01:29.187822+0000 /workdir/src/testing/.libs/test_kyc_api-17359 ERROR Command kyc-do (testing_api_cmd_kyc_proof.c:192) did not complete (at pay)
FAIL test_kyc_api (exit status: 1)
```

Christian Grothoff

2024-01-30 21:23

manager   ~0021096

dd12062b..0b85c6cc adds some missing taler-exchange-kyc*.sh scripts to the Debian packages of the *exchange*. This might explain the failure. But, if I understand correctly, I think I need to wait for the nightly Debian package build before I'll see this in the local CI script, correct?

Christian Grothoff

2024-01-30 21:25

manager   ~0021097

I'm pretty sure a re-built of the exchange packages will fix it, as I can fully reproduce the problem OUTSIDE of CI/CD if I just

$ rm $PREFIX/bin/taler-exchange-kyc-oauth2-test-converter.sh

which is one of the files that was missing in the Debian package of libtalerexchange-dev

Christian Grothoff

2024-01-31 14:06

manager   ~0021112

test_kyc_api now also fails, but it seems the test suite overall runs into a timeout. Not sure why, if it actually takes longer (strange, no activity at the end!), or if there is some stale process that keeps it hit the timeout. But that is how/why it appears to fail right now.

dvn

2024-02-01 16:47

developer   ~0021118

Last edited: 2024-02-01 16:48

 What happens when you run it locally? The timeout is from buildbot, but does it hang the same way?

Christian Grothoff

2024-02-01 20:58

manager   ~0021121

Yes, also locally. Seems taler-wallet-cli hangs in 'run-until-done' for several minutes...

Christian Grothoff

2024-02-01 21:18

manager   ~0021122

Ok, right now 'make check' also hangs outside of CI/CD in the same way, plus the wallet-test that is being skipped by the CI/CD *fails*. I think this is a wallet-core regression => @Fdold.

Florian Dold

2024-02-01 22:16

manager   ~0021123

Almost all taler-harness tests are failing right now because libeufin implements a different variation the withdrawal op confirmation endpoint than fakebank ...

Christian Grothoff

2024-02-01 22:25

manager   ~0021124

Eh, did we not say something about "no more breaking changes"? Were they always different? Why is there no open bug on resolving the difference?

Florian Dold

2024-02-01 23:45

manager   ~0021125

Both libeufin and the SPA support only the new version (with /accounts/$acct/ as prefix).

Thus I assumed that this was a coordinated change that happened in the first week of Jan where I was off and I simply missed the memo ...

Christian Grothoff

2024-02-05 11:34

manager   ~0021148

a24a8eef..14ccce8f updates the fakebank implementation to support the v4 API. With that, 'make check' again passes. Need to wait for exchange package update to see about the merchant CI/CD.

dvn

2024-02-05 18:00

developer   ~0021159

It appears that the tests jobs are passing now.

Christian Grothoff

2024-02-05 22:07

manager   ~0021165

Buildbot just passed!

Issue History

Date Modified Username Field Change
2024-01-23 17:54 dvn New Issue
2024-01-23 17:54 dvn Status new => assigned
2024-01-23 17:54 dvn Assigned To => oec
2024-01-23 17:55 dvn Relationship added related to 0008148
2024-01-23 18:02 oec Note Added: 0020997
2024-01-24 11:50 oec Note Added: 0021018
2024-01-24 11:51 oec Assigned To oec => Christian Grothoff
2024-01-24 11:51 oec Status assigned => feedback
2024-01-24 11:51 oec Note Added: 0021019
2024-01-25 15:04 oec Target Version => 0.9.4
2024-01-27 01:07 Christian Grothoff Relationship added child of 0008153
2024-01-29 15:10 oec Assigned To Christian Grothoff => oec
2024-01-30 13:46 oec Status feedback => resolved
2024-01-30 13:46 oec Resolution open => fixed
2024-01-30 13:46 oec Fixed in Version => git (master)
2024-01-30 13:46 oec Note Added: 0021091
2024-01-30 14:06 oec Assigned To oec => Christian Grothoff
2024-01-30 14:06 oec Status resolved => feedback
2024-01-30 14:06 oec Resolution fixed => reopened
2024-01-30 14:06 oec Note Added: 0021093
2024-01-30 14:07 oec Status feedback => assigned
2024-01-30 14:29 oec Description Updated
2024-01-30 21:23 Christian Grothoff Note Added: 0021096
2024-01-30 21:25 Christian Grothoff Note Added: 0021097
2024-01-31 14:05 Christian Grothoff Assigned To Christian Grothoff => dvn
2024-01-31 14:06 Christian Grothoff Note Added: 0021112
2024-01-31 16:03 oec Fixed in Version git (master) =>
2024-02-01 16:47 dvn Note Added: 0021118
2024-02-01 16:48 dvn Note Edited: 0021118
2024-02-01 20:58 Christian Grothoff Note Added: 0021121
2024-02-01 20:58 Christian Grothoff Assigned To dvn => Florian Dold
2024-02-01 21:18 Christian Grothoff Note Added: 0021122
2024-02-01 22:16 Florian Dold Note Added: 0021123
2024-02-01 22:25 Christian Grothoff Note Added: 0021124
2024-02-01 23:45 Florian Dold Note Added: 0021125
2024-02-05 10:15 Christian Grothoff Assigned To Florian Dold => Christian Grothoff
2024-02-05 11:34 Christian Grothoff Note Added: 0021148
2024-02-05 18:00 dvn Note Added: 0021159
2024-02-05 22:07 Christian Grothoff Status assigned => resolved
2024-02-05 22:07 Christian Grothoff Fixed in Version => 0.9.4
2024-02-05 22:07 Christian Grothoff Note Added: 0021165
2024-03-07 20:47 Christian Grothoff Status resolved => closed