View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0007965Talermechant backendpublic2023-10-18 20:442024-01-12 14:04
ReporterFlorian Dold Assigned ToFlorian Dold  
PrioritynormalSeverityminorReproducibilityhave not tried
Status closedResolutionfixed 
Target Version0.9.3Fixed in Version0.9.3 
Summary0007965: merchant puts only one exchange in contract terms despite multiple exchanges in the config
DescriptionTwo exchanges are configured for KUDOS:

root@07aa93b48af6:/# taler-config -c /etc/taler/taler.conf -s merchant-exchange-kudos
CURRENCY = KUDOS
MASTER_KEY = JFX1NE38C65A5XT8VSNQXX7R7BBG4GNZ63F5T7Y6859V4J8KBKF0
EXCHANGE_BASE_URL = https://exchange.demo.taler.net/
root@07aa93b48af6:/# taler-config -c /etc/taler/taler.conf -s merchant-exchange-sandcastle
CURRENCY = KUDOS
MASTER_KEY = EZQXVKMHXVA9CB1G6E7CC70KZ0ZJAHVR1E38HK356RTZJQSD85RG
EXCHANGE_BASE_URL = https://exchange.taler.fdold.eu/

But the contract terms only contain one:

  exchanges: [
    {
      url: 'https://exchange.demo.taler.net/',
      priority: 1024,
      master_pub: 'QXRM4H6AM34GVY6QDQ8NVHBKV2NCN1095VXSPRWRW7V70QGFYH30'
    }
  ],
TagsNo tags attached.

Activities

Christian Grothoff

2023-10-29 16:06

manager   ~0020610

Well, there was some logic that was sub-optimal especially if one exchange had answered /keys and the other one took more than 2s to answer. I've now fixed that, so that we wait for the 120s of the long-poll timeout for each exchange upon first contact, and then use the exchanges that are ready. The POST /private/orders *fails* if there are zero acceptable exchanges (with a 409) for the given currency/wire method, and otherwise returns the subset of trusted exchanges for which we have /keys. So this may still result in fewer exchanges in the contract than configured *if* those exchanges do not run a compatible protocol version or if they are down.

Christian Grothoff

2023-10-29 16:06

manager   ~0020611

I don't have a good reproducer, can you test that the fix works as intended easily?

Florian Dold

2023-11-13 18:41

manager   ~0020636

Actually the current behavior is that the merchant *hangs* when two exchanges are configured. See attached logs.

Can be reproduced with:

$ taler-harness run-integrationtests multi-exchange
merchant-testmerchant-1-stderr.log (39,871 bytes)    
2023-11-13T18:32:23.585979+0100 taler-merchant-httpd-364050 INFO Starting taler-merchant-httpd
2023-11-13T18:32:23.892280+0100 taler-merchant-httpd-364050 INFO Change in PQ event FD to -1
2023-11-13T18:32:23.892293+0100 taler-merchant-httpd-364050 INFO New poll FD is -1
2023-11-13T18:32:23.894982+0100 taler-merchant-httpd-364050 INFO Change in PQ event FD to 7
2023-11-13T18:32:23.894989+0100 taler-merchant-httpd-364050 INFO New poll FD is 7
2023-11-13T18:32:23.895003+0100 taler-merchant-httpd-364050 INFO Starting event scheduler
2023-11-13T18:32:23.895007+0100 taler-merchant-httpd-364050 INFO New poll FD is 7
2023-11-13T18:32:23.895011+0100 taler-merchant-httpd-364050 INFO Activating poll job on 7
2023-11-13T18:32:23.895020+0100 taler-merchant-httpd-364050 INFO Executing PQ command `LISTEN XW9K15VBEKGDMCMN31SKH75KVXND1GTW5MW7WME4CMPQ0X9ECWTR0'
2023-11-13T18:32:23.895407+0100 taler-merchant-httpd-364050 INFO Setup exchange http://localhost:8281/ as trusted
2023-11-13T18:32:23.895453+0100 taler-merchant-httpd-364050 INFO Setup exchange http://localhost:8081/ as trusted
2023-11-13T18:32:23.895488+0100 taler-merchant-httpd-364050 INFO Setup exchange https://exchange.demo.taler.net/ as trusted
2023-11-13T18:32:23.895493+0100 taler-merchant-httpd-364050 INFO Executing PQ command `LISTEN XN0RW6KT8Y9MK75YM85SC7GTA6SC5W91FXWDQP0ZB42GY3E52DZH0'
2023-11-13T18:32:23.895521+0100 taler-merchant-httpd-364050 INFO Received instance settings notification: reload `(null)'
2023-11-13T18:32:23.896367+0100 taler-merchant-httpd-364050 INFO Fetching /keys from exchange http://localhost:8281/ in retry_exchange()
2023-11-13T18:32:23.896404+0100 taler-merchant-httpd-364050 INFO Fetching /keys from exchange http://localhost:8081/ in retry_exchange()
2023-11-13T18:32:23.896412+0100 taler-merchant-httpd-364050 INFO Fetching /keys from exchange https://exchange.demo.taler.net/ in retry_exchange()
2023-11-13T18:32:23.896419+0100 taler-merchant-httpd-364050 INFO PG poll job active
2023-11-13T18:32:23.896424+0100 taler-merchant-httpd-364050 INFO PG poll job finishes after 0 events
2023-11-13T18:32:23.896427+0100 taler-merchant-httpd-364050 INFO Resubscribing
*   Trying 127.0.0.1:8281...
*   Trying 127.0.0.1:8081...
* Connected to localhost (127.0.0.1) port 8281 (#0)
> GET /keys HTTP/1.1
Host: localhost:8281
Accept: */*
Accept-Encoding: deflate, gzip
Content-Type: application/json

* Connected to localhost (127.0.0.1) port 8081 (#1)
> GET /keys HTTP/1.1
Host: localhost:8081
Accept: */*
Accept-Encoding: deflate, gzip
Content-Type: application/json

*   Trying [2a07:6b47:100:464:225:90ff:fe93:72cf]:443...
< HTTP/1.1 200 OK
< Date: Mon, 13 Nov 2023 17:32:23 GMT
< Connection: close
< Content-Encoding: deflate
< Access-Control-Allow-Origin: *
< Access-Control-Expose-Headers: *
< Content-Type: application/json
< Last-Modified: Mon, 13 Nov 2023 17:32:21 GMT
< Expires: Mon, 05 Feb 2024 17:32:23 GMT
2023-11-13T18:32:23.898176+0100 taler-merchant-httpd-364050 INFO Found Expires header `Mon, 05 Feb 2024 17:32:23 GMT
'
< Vary: Accept-Encoding
< Cache-Control: public,max-age=3600
< Vary: Accept-Encoding
< Cache-Control: public,max-age=86400
< ETag: MMJHFZ98DETAFPPN8ET6VPD1F8G2MZZ5RPJAFDGAZJ780FSEG6TVNPSJXQ120YW59V9HH1WQ2AZFJ39HR0RMT2AVDMNBTJDAJFVBQBG
< Content-Length: 3369
< 
* Closing connection 1
2023-11-13T18:32:23.898351+0100 taler-merchant-httpd-364050 INFO Received keys from URL `http://localhost:8081/keys' with status 200 and expiration Mon Feb 05 17:32:23 2024.
2023-11-13T18:32:23.898746+0100 taler-merchant-httpd-364050 INFO Parsed 1 wire accounts from JSON
2023-11-13T18:32:23.899153+0100 taler-merchant-httpd-364050 INFO Starting merchant DB transaction `update exchange key data'
2023-11-13T18:32:23.900334+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Fri Jan 01 01:00:00 2027 of TESTKUDOS:0.01
2023-11-13T18:32:23.900586+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Thu Jan 01 01:00:00 2026 of TESTKUDOS:0.01
2023-11-13T18:32:23.900636+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Wed Jan 01 01:00:00 2025 of TESTKUDOS:0.01
2023-11-13T18:32:23.900671+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Mon Jan 01 01:00:00 2024 of TESTKUDOS:0.01
2023-11-13T18:32:23.900704+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Sun Jan 01 01:00:00 2023 of TESTKUDOS:0.01
2023-11-13T18:32:23.900734+0100 taler-merchant-httpd-364050 INFO Executing command `NOTIFY XW9K15VBEKGDMCMN31SKH75KVXND1GTW5MW7WME4CMPQ0X9ECWTR0, 'D1T78W1T5WQPRVV3C5P6GVVKEGX3GC1R64QG0''
2023-11-13T18:32:23.900753+0100 taler-merchant-httpd-364050 INFO PG poll job active
2023-11-13T18:32:23.900757+0100 taler-merchant-httpd-364050 INFO PG poll job finishes after 0 events
2023-11-13T18:32:23.900761+0100 taler-merchant-httpd-364050 INFO Committing merchant DB transaction update exchange key data
2023-11-13T18:32:23.912149+0100 taler-merchant-httpd-364050 INFO Starting merchant DB transaction `update exchange key data'
2023-11-13T18:32:23.912584+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Fri Jan 01 01:00:00 2027 of TESTKUDOS:0.01
2023-11-13T18:32:23.912623+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Thu Jan 01 01:00:00 2026 of TESTKUDOS:0.01
2023-11-13T18:32:23.912653+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Wed Jan 01 01:00:00 2025 of TESTKUDOS:0.01
2023-11-13T18:32:23.912679+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Mon Jan 01 01:00:00 2024 of TESTKUDOS:0.01
2023-11-13T18:32:23.912705+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Sun Jan 01 01:00:00 2023 of TESTKUDOS:0.01
2023-11-13T18:32:23.912730+0100 taler-merchant-httpd-364050 INFO Executing command `NOTIFY XW9K15VBEKGDMCMN31SKH75KVXND1GTW5MW7WME4CMPQ0X9ECWTR0, 'D1T78W1T5WQPRVV3C5P6GVVKEGX3GC1R64QG0''
2023-11-13T18:32:23.912749+0100 taler-merchant-httpd-364050 INFO PG poll job active
2023-11-13T18:32:23.912759+0100 taler-merchant-httpd-364050 INFO Received notification xw9k15vbekgdmcmn31skh75kvxnd1gtw5mw7wme4cmpq0x9ecwtr0 with extra data `http://localhost:8081/'
2023-11-13T18:32:23.912765+0100 taler-merchant-httpd-364050 INFO Received keys change notification: reload `http://localhost:8081/'
2023-11-13T18:32:23.913154+0100 taler-merchant-httpd-364050 INFO Parsed 1 wire accounts from JSON
2023-11-13T18:32:23.913219+0100 taler-merchant-httpd-364050 INFO Loaded /keys from database with 1 accounts
2023-11-13T18:32:23.913225+0100 taler-merchant-httpd-364050 INFO Reloaded /keys of http://localhost:8081/ from database
2023-11-13T18:32:23.913230+0100 taler-merchant-httpd-364050 INFO Processing find operations for `http://localhost:8081/' (2)
2023-11-13T18:32:23.913235+0100 taler-merchant-httpd-364050 INFO PG poll job finishes after 1 events
2023-11-13T18:32:23.913238+0100 taler-merchant-httpd-364050 INFO Committing merchant DB transaction update exchange key data
2023-11-13T18:32:23.915417+0100 taler-merchant-httpd-364050 INFO Starting merchant DB transaction `update exchange key data'
2023-11-13T18:32:23.915779+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Fri Jan 01 01:00:00 2027 of TESTKUDOS:0.01
2023-11-13T18:32:23.915820+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Thu Jan 01 01:00:00 2026 of TESTKUDOS:0.01
2023-11-13T18:32:23.915853+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Wed Jan 01 01:00:00 2025 of TESTKUDOS:0.01
2023-11-13T18:32:23.915885+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Mon Jan 01 01:00:00 2024 of TESTKUDOS:0.01
2023-11-13T18:32:23.915916+0100 taler-merchant-httpd-364050 INFO Storing wire fee for XHQW03N8 starting at Sun Jan 01 01:00:00 2023 of TESTKUDOS:0.01
2023-11-13T18:32:23.915944+0100 taler-merchant-httpd-364050 INFO Executing command `NOTIFY XW9K15VBEKGDMCMN31SKH75KVXND1GTW5MW7WME4CMPQ0X9ECWTR0, 'D1T78W1T5WQPRVV3C5P6GVVKEGX3GC1R64QG0''
2023-11-13T18:32:23.915966+0100 taler-merchant-httpd-364050 INFO PG poll job active
2023-11-13T18:32:23.915974+0100 taler-merchant-httpd-364050 INFO Received notification xw9k15vbekgdmcmn31skh75kvxnd1gtw5mw7wme4cmpq0x9ecwtr0 with extra data `http://localhost:8081/'
2023-11-13T18:32:23.915981+0100 taler-merchant-httpd-364050 INFO Received keys change notification: reload `http://localhost:8081/'
2023-11-13T18:32:23.916448+0100 taler-merchant-httpd-364050 INFO Parsed 1 wire accounts from JSON
2023-11-13T18:32:23.916505+0100 taler-merchant-httpd-364050 INFO Loaded /keys from database with 1 accounts
2023-11-13T18:32:23.916513+0100 taler-merchant-httpd-364050 INFO Reloaded /keys of http://localhost:8081/ from database
2023-11-13T18:32:23.916521+0100 taler-merchant-httpd-364050 INFO Processing find operations for `http://localhost:8081/' (2)
2023-11-13T18:32:23.916525+0100 taler-merchant-httpd-364050 INFO PG poll job finishes after 1 events
2023-11-13T18:32:23.916528+0100 taler-merchant-httpd-364050 INFO Committing merchant DB transaction update exchange key data
2023-11-13T18:32:23.918716+0100 taler-merchant-httpd-364050 INFO HTTP request for `http://localhost:8081/keys' finished with 200 after 1847 µs
* Connected to exchange.demo.taler.net (2a07:6b47:100:464:225:90ff:fe93:72cf) port 443 (#2)
* ALPN: offers h2,http/1.1
*  CAfile: /etc/pki/tls/certs/ca-bundle.crt
*  CApath: none
2023-11-13T18:32:24.060405+0100 taler-merchant-httpd-364050(KB0FK70GCWPNAJJM5PP4YQ9QER) INFO Handling request (GET) for URL '/config'
2023-11-13T18:32:24.060504+0100 taler-merchant-httpd-364050(KB0FK70GCWPNAJJM5PP4YQ9QER) INFO Request for `/config' completed with HTTP status 200 (0)
2023-11-13T18:32:24.061406+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Handling request (POST) for URL '/management/instances'
2023-11-13T18:32:24.061538+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Starting merchant DB transaction `post /instances'
2023-11-13T18:32:24.062214+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Committing merchant DB transaction post /instances
2023-11-13T18:32:24.073427+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Generating instance settings notification: reload `default'
2023-11-13T18:32:24.073434+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Executing command `NOTIFY XN0RW6KT8Y9MK75YM85SC7GTA6SC5W91FXWDQP0ZB42GY3E52DZH0, 'CHJPCRBNDHT00''
2023-11-13T18:32:24.073470+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO PG poll job active
2023-11-13T18:32:24.073476+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Received notification xw9k15vbekgdmcmn31skh75kvxnd1gtw5mw7wme4cmpq0x9ecwtr0 with extra data `http://localhost:8081/'
2023-11-13T18:32:24.073482+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Received keys change notification: reload `http://localhost:8081/'
2023-11-13T18:32:24.073922+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Parsed 1 wire accounts from JSON
2023-11-13T18:32:24.073994+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Loaded /keys from database with 1 accounts
2023-11-13T18:32:24.074000+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Reloaded /keys of http://localhost:8081/ from database
2023-11-13T18:32:24.074008+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Processing find operations for `http://localhost:8081/' (2)
2023-11-13T18:32:24.074013+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Received notification xn0rw6kt8y9mk75ym85sc7gta6sc5w91fxwdqp0zb42gy3e52dzh0 with extra data `default'
2023-11-13T18:32:24.074018+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Received instance settings notification: reload `default'
2023-11-13T18:32:24.074368+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO PG poll job finishes after 2 events
2023-11-13T18:32:24.074394+0100 taler-merchant-httpd-364050(GQRTYED5A362SZ10XPTRPR1RK0) INFO Request for `/management/instances' completed with HTTP status 204 (0)
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN: server accepted http/1.1
* Server certificate:
*  subject: CN=gv.taler.net
*  start date: Oct 31 10:01:31 2023 GMT
*  expire date: Jan 29 10:01:30 2024 GMT
*  subjectAltName: host "exchange.demo.taler.net" matched cert's "exchange.demo.taler.net"
*  issuer: C=US; O=Let's Encrypt; CN=R3
*  SSL certificate verify ok.
* using HTTP/1.1
> GET /keys HTTP/1.1
Host: exchange.demo.taler.net
Accept: */*
Accept-Encoding: deflate, gzip
Content-Type: application/json

2023-11-13T18:32:24.075121+0100 taler-merchant-httpd-364050(7YWXMNPP28TDMC5SH7AKTDE7Z4) INFO Handling request (POST) for URL '/instances/default/private/accounts'
2023-11-13T18:32:24.077581+0100 taler-merchant-httpd-364050(7YWXMNPP28TDMC5SH7AKTDE7Z4) INFO Executing command `NOTIFY XDQM4Z4N0D3GX0H9JEXH70EBC2T3KY7HC0TJB0Z60D2H781RXR6AG, '''
2023-11-13T18:32:24.077621+0100 taler-merchant-httpd-364050(7YWXMNPP28TDMC5SH7AKTDE7Z4) INFO PG poll job active
2023-11-13T18:32:24.077627+0100 taler-merchant-httpd-364050(7YWXMNPP28TDMC5SH7AKTDE7Z4) INFO PG poll job finishes after 0 events
2023-11-13T18:32:24.077632+0100 taler-merchant-httpd-364050(7YWXMNPP28TDMC5SH7AKTDE7Z4) INFO Generating instance settings notification: reload `default'
2023-11-13T18:32:24.077637+0100 taler-merchant-httpd-364050(7YWXMNPP28TDMC5SH7AKTDE7Z4) INFO Executing command `NOTIFY XN0RW6KT8Y9MK75YM85SC7GTA6SC5W91FXWDQP0ZB42GY3E52DZH0, 'CHJPCRBNDHT00''
2023-11-13T18:32:24.077664+0100 taler-merchant-httpd-364050(7YWXMNPP28TDMC5SH7AKTDE7Z4) INFO PG poll job active
2023-11-13T18:32:24.077670+0100 taler-merchant-httpd-364050(7YWXMNPP28TDMC5SH7AKTDE7Z4) INFO Received notification xn0rw6kt8y9mk75ym85sc7gta6sc5w91fxwdqp0zb42gy3e52dzh0 with extra data `default'
2023-11-13T18:32:24.077675+0100 taler-merchant-httpd-364050(7YWXMNPP28TDMC5SH7AKTDE7Z4) INFO Received instance settings notification: reload `default'
2023-11-13T18:32:24.077844+0100 taler-merchant-httpd-364050(7YWXMNPP28TDMC5SH7AKTDE7Z4) INFO PG poll job finishes after 1 events
2023-11-13T18:32:24.077880+0100 taler-merchant-httpd-364050(7YWXMNPP28TDMC5SH7AKTDE7Z4) INFO Request for `/instances/default/private/accounts' completed with HTTP status 200 (0)
2023-11-13T18:32:24.078579+0100 taler-merchant-httpd-364050(T50BA0Q5HRE809VVPJM3CKW68G) INFO Handling request (POST) for URL '/management/instances'
2023-11-13T18:32:24.078612+0100 taler-merchant-httpd-364050(T50BA0Q5HRE809VVPJM3CKW68G) INFO Starting merchant DB transaction `post /instances'
2023-11-13T18:32:24.078730+0100 taler-merchant-httpd-364050(T50BA0Q5HRE809VVPJM3CKW68G) INFO Committing merchant DB transaction post /instances
2023-11-13T18:32:24.080881+0100 taler-merchant-httpd-364050(T50BA0Q5HRE809VVPJM3CKW68G) INFO Generating instance settings notification: reload `minst1'
2023-11-13T18:32:24.080887+0100 taler-merchant-httpd-364050(T50BA0Q5HRE809VVPJM3CKW68G) INFO Executing command `NOTIFY XN0RW6KT8Y9MK75YM85SC7GTA6SC5W91FXWDQP0ZB42GY3E52DZH0, 'DNMPWWVM6400''
2023-11-13T18:32:24.080918+0100 taler-merchant-httpd-364050(T50BA0Q5HRE809VVPJM3CKW68G) INFO PG poll job active
2023-11-13T18:32:24.080923+0100 taler-merchant-httpd-364050(T50BA0Q5HRE809VVPJM3CKW68G) INFO Received notification xn0rw6kt8y9mk75ym85sc7gta6sc5w91fxwdqp0zb42gy3e52dzh0 with extra data `minst1'
2023-11-13T18:32:24.080928+0100 taler-merchant-httpd-364050(T50BA0Q5HRE809VVPJM3CKW68G) INFO Received instance settings notification: reload `minst1'
2023-11-13T18:32:24.081074+0100 taler-merchant-httpd-364050(T50BA0Q5HRE809VVPJM3CKW68G) INFO PG poll job finishes after 1 events
2023-11-13T18:32:24.081094+0100 taler-merchant-httpd-364050(T50BA0Q5HRE809VVPJM3CKW68G) INFO Request for `/management/instances' completed with HTTP status 204 (0)
2023-11-13T18:32:24.081672+0100 taler-merchant-httpd-364050(29M6S3EJARWQK1VH1SPRSM63RM) INFO Handling request (POST) for URL '/instances/minst1/private/accounts'
2023-11-13T18:32:24.083859+0100 taler-merchant-httpd-364050(29M6S3EJARWQK1VH1SPRSM63RM) INFO Executing command `NOTIFY XDQM4Z4N0D3GX0H9JEXH70EBC2T3KY7HC0TJB0Z60D2H781RXR6AG, '''
2023-11-13T18:32:24.083891+0100 taler-merchant-httpd-364050(29M6S3EJARWQK1VH1SPRSM63RM) INFO PG poll job active
2023-11-13T18:32:24.083896+0100 taler-merchant-httpd-364050(29M6S3EJARWQK1VH1SPRSM63RM) INFO PG poll job finishes after 0 events
2023-11-13T18:32:24.083900+0100 taler-merchant-httpd-364050(29M6S3EJARWQK1VH1SPRSM63RM) INFO Generating instance settings notification: reload `minst1'
2023-11-13T18:32:24.083905+0100 taler-merchant-httpd-364050(29M6S3EJARWQK1VH1SPRSM63RM) INFO Executing command `NOTIFY XN0RW6KT8Y9MK75YM85SC7GTA6SC5W91FXWDQP0ZB42GY3E52DZH0, 'DNMPWWVM6400''
2023-11-13T18:32:24.083929+0100 taler-merchant-httpd-364050(29M6S3EJARWQK1VH1SPRSM63RM) INFO PG poll job active
2023-11-13T18:32:24.083934+0100 taler-merchant-httpd-364050(29M6S3EJARWQK1VH1SPRSM63RM) INFO Received notification xn0rw6kt8y9mk75ym85sc7gta6sc5w91fxwdqp0zb42gy3e52dzh0 with extra data `minst1'
2023-11-13T18:32:24.083939+0100 taler-merchant-httpd-364050(29M6S3EJARWQK1VH1SPRSM63RM) INFO Received instance settings notification: reload `minst1'
2023-11-13T18:32:24.084085+0100 taler-merchant-httpd-364050(29M6S3EJARWQK1VH1SPRSM63RM) INFO PG poll job finishes after 1 events
2023-11-13T18:32:24.084107+0100 taler-merchant-httpd-364050(29M6S3EJARWQK1VH1SPRSM63RM) INFO Request for `/instances/minst1/private/accounts' completed with HTTP status 200 (0)
* old SSL session ID is stale, removing
< HTTP/1.1 200 OK
< Server: nginx
< Date: Mon, 13 Nov 2023 17:32:21 GMT
< Content-Type: application/json
< Content-Length: 3636
< Connection: keep-alive
< Content-Encoding: deflate
< Access-Control-Allow-Origin: *
< Access-Control-Expose-Headers: *
< Last-Modified: Mon, 13 Nov 2023 16:53:18 GMT
< Expires: Mon, 01 Jan 2024 00:00:00 GMT
2023-11-13T18:32:24.108427+0100 taler-merchant-httpd-364050 INFO Found Expires header `Mon, 01 Jan 2024 00:00:00 GMT
'
< Vary: Accept-Encoding
< Cache-Control: public,max-age=3600
< ETag: 6RVT19R1YJ7W25MZ929CH6GVPEW8H46DRGVK3WW794YZ2E7C30VB3QJ6ZY975APQH5K491HRTEF1BWK1AG1GZJJ3A0BATFKDSGMF8Z0
< Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
< X-XSS-Protection: 1; mode=block
< X-Frame-Options: SAMEORIGIN
< X-Content-Type-Options: nosniff
< Content-Security-Policy: default-src 'self' https://www.taler.net/dist/; img-src 'self' https://unpkg.com/ https://secure.gravatar.com/ https://git.taler.net/ data: blob:; script-src 'self' 'unsafe-inline' 'unsafe-eval' https://www.taler.net/dist/js/; style-src 'self' 'unsafe-inline' https://www.taler.net/dist/css/; connect-src 'self' wss://buildbot.taler.net; object-src 'self' blob:; font-src 'self' data:
< Referrer-Policy: same-origin
< 
* Connection #2 to host exchange.demo.taler.net left intact
2023-11-13T18:32:24.108588+0100 taler-merchant-httpd-364050 INFO Received keys from URL `https://exchange.demo.taler.net/keys' with status 200 and expiration Mon Jan 01 00:00:00 2024.
2023-11-13T18:32:24.108603+0100 taler-merchant-httpd-364050 WARNING Parsing /keys failed for `currency_specification' (9)
2023-11-13T18:32:24.108608+0100 taler-merchant-httpd-364050 ERROR Assertion failed at exchange_api_handle.c:924.
2023-11-13T18:32:24.108611+0100 taler-merchant-httpd-364050 ERROR Could not decode /keys response
2023-11-13T18:32:24.108621+0100 taler-merchant-httpd-364050 WARNING Failed to fetch /keys from `https://exchange.demo.taler.net/'; retrying in 5 ms
2023-11-13T18:32:24.108632+0100 taler-merchant-httpd-364050 INFO HTTP request for `https://exchange.demo.taler.net/keys' finished with 200 after 212 ms
2023-11-13T18:32:24.113988+0100 taler-merchant-httpd-364050 INFO Fetching /keys from exchange https://exchange.demo.taler.net/ in retry_exchange()
* Found bundle for host: 0xe7fc90 [serially]
* Can not multiplex, even if we wanted to
* Re-using existing connection #2 with host exchange.demo.taler.net
> GET /keys HTTP/1.1
Host: exchange.demo.taler.net
Accept: */*
Accept-Encoding: deflate, gzip
Content-Type: application/json

< HTTP/1.1 200 OK
< Server: nginx
< Date: Mon, 13 Nov 2023 17:32:21 GMT
< Content-Type: application/json
< Content-Length: 3636
< Connection: keep-alive
< Content-Encoding: deflate
< Access-Control-Allow-Origin: *
< Access-Control-Expose-Headers: *
< Last-Modified: Mon, 13 Nov 2023 16:53:18 GMT
< Expires: Mon, 01 Jan 2024 00:00:00 GMT
2023-11-13T18:32:24.261356+0100 taler-merchant-httpd-364050 INFO Found Expires header `Mon, 01 Jan 2024 00:00:00 GMT
'
< Vary: Accept-Encoding
< Cache-Control: public,max-age=3600
< ETag: 6RVT19R1YJ7W25MZ929CH6GVPEW8H46DRGVK3WW794YZ2E7C30VB3QJ6ZY975APQH5K491HRTEF1BWK1AG1GZJJ3A0BATFKDSGMF8Z0
< Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
< X-XSS-Protection: 1; mode=block
< X-Frame-Options: SAMEORIGIN
< X-Content-Type-Options: nosniff
< Content-Security-Policy: default-src 'self' https://www.taler.net/dist/; img-src 'self' https://unpkg.com/ https://secure.gravatar.com/ https://git.taler.net/ data: blob:; script-src 'self' 'unsafe-inline' 'unsafe-eval' https://www.taler.net/dist/js/; style-src 'self' 'unsafe-inline' https://www.taler.net/dist/css/; connect-src 'self' wss://buildbot.taler.net; object-src 'self' blob:; font-src 'self' data:
< Referrer-Policy: same-origin
< 
* Connection #2 to host exchange.demo.taler.net left intact
2023-11-13T18:32:24.261529+0100 taler-merchant-httpd-364050 INFO Received keys from URL `https://exchange.demo.taler.net/keys' with status 200 and expiration Mon Jan 01 00:00:00 2024.
2023-11-13T18:32:24.261543+0100 taler-merchant-httpd-364050 WARNING Parsing /keys failed for `currency_specification' (9)
2023-11-13T18:32:24.261547+0100 taler-merchant-httpd-364050 ERROR Assertion failed at exchange_api_handle.c:924.
2023-11-13T18:32:24.261551+0100 taler-merchant-httpd-364050 ERROR Could not decode /keys response
2023-11-13T18:32:24.261558+0100 taler-merchant-httpd-364050 WARNING Failed to fetch /keys from `https://exchange.demo.taler.net/'; retrying in 23 ms
2023-11-13T18:32:24.261569+0100 taler-merchant-httpd-364050 INFO HTTP request for `https://exchange.demo.taler.net/keys' finished with 200 after 147 ms
2023-11-13T18:32:24.285404+0100 taler-merchant-httpd-364050 INFO Fetching /keys from exchange https://exchange.demo.taler.net/ in retry_exchange()
* Found bundle for host: 0xe7fc90 [serially]
* Can not multiplex, even if we wanted to
* Re-using existing connection #2 with host exchange.demo.taler.net
> GET /keys HTTP/1.1
Host: exchange.demo.taler.net
Accept: */*
Accept-Encoding: deflate, gzip
Content-Type: application/json

< HTTP/1.1 200 OK
< Server: nginx
< Date: Mon, 13 Nov 2023 17:32:21 GMT
< Content-Type: application/json
< Content-Length: 3636
< Connection: keep-alive
< Content-Encoding: deflate
< Access-Control-Allow-Origin: *
< Access-Control-Expose-Headers: *
< Last-Modified: Mon, 13 Nov 2023 16:53:18 GMT
< Expires: Mon, 01 Jan 2024 00:00:00 GMT
2023-11-13T18:32:24.309652+0100 taler-merchant-httpd-364050 INFO Found Expires header `Mon, 01 Jan 2024 00:00:00 GMT
'
< Vary: Accept-Encoding
< Cache-Control: public,max-age=3600
< ETag: 6RVT19R1YJ7W25MZ929CH6GVPEW8H46DRGVK3WW794YZ2E7C30VB3QJ6ZY975APQH5K491HRTEF1BWK1AG1GZJJ3A0BATFKDSGMF8Z0
< Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
< X-XSS-Protection: 1; mode=block
< X-Frame-Options: SAMEORIGIN
< X-Content-Type-Options: nosniff
< Content-Security-Policy: default-src 'self' https://www.taler.net/dist/; img-src 'self' https://unpkg.com/ https://secure.gravatar.com/ https://git.taler.net/ data: blob:; script-src 'self' 'unsafe-inline' 'unsafe-eval' https://www.taler.net/dist/js/; style-src 'self' 'unsafe-inline' https://www.taler.net/dist/css/; connect-src 'self' wss://buildbot.taler.net; object-src 'self' blob:; font-src 'self' data:
< Referrer-Policy: same-origin
< 
* Connection #2 to host exchange.demo.taler.net left intact
2023-11-13T18:32:24.309862+0100 taler-merchant-httpd-364050 INFO Received keys from URL `https://exchange.demo.taler.net/keys' with status 200 and expiration Mon Jan 01 00:00:00 2024.
2023-11-13T18:32:24.309877+0100 taler-merchant-httpd-364050 WARNING Parsing /keys failed for `currency_specification' (9)
2023-11-13T18:32:24.309883+0100 taler-merchant-httpd-364050 ERROR Assertion failed at exchange_api_handle.c:924.
2023-11-13T18:32:24.309888+0100 taler-merchant-httpd-364050 ERROR Could not decode /keys response
2023-11-13T18:32:24.309896+0100 taler-merchant-httpd-364050 WARNING Failed to fetch /keys from `https://exchange.demo.taler.net/'; retrying in 103 ms
2023-11-13T18:32:24.309911+0100 taler-merchant-httpd-364050 INFO HTTP request for `https://exchange.demo.taler.net/keys' finished with 200 after 24 ms
2023-11-13T18:32:24.413321+0100 taler-merchant-httpd-364050 INFO Fetching /keys from exchange https://exchange.demo.taler.net/ in retry_exchange()
* Found bundle for host: 0xe7fc90 [serially]
* Can not multiplex, even if we wanted to
* Re-using existing connection #2 with host exchange.demo.taler.net
> GET /keys HTTP/1.1
Host: exchange.demo.taler.net
Accept: */*
Accept-Encoding: deflate, gzip
Content-Type: application/json

< HTTP/1.1 200 OK
< Server: nginx
< Date: Mon, 13 Nov 2023 17:32:21 GMT
< Content-Type: application/json
< Content-Length: 3636
< Connection: keep-alive
< Content-Encoding: deflate
< Access-Control-Allow-Origin: *
< Access-Control-Expose-Headers: *
< Last-Modified: Mon, 13 Nov 2023 16:53:18 GMT
< Expires: Mon, 01 Jan 2024 00:00:00 GMT
2023-11-13T18:32:24.509335+0100 taler-merchant-httpd-364050 INFO Found Expires header `Mon, 01 Jan 2024 00:00:00 GMT
'
< Vary: Accept-Encoding
< Cache-Control: public,max-age=3600
< ETag: 6RVT19R1YJ7W25MZ929CH6GVPEW8H46DRGVK3WW794YZ2E7C30VB3QJ6ZY975APQH5K491HRTEF1BWK1AG1GZJJ3A0BATFKDSGMF8Z0
< Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
< X-XSS-Protection: 1; mode=block
< X-Frame-Options: SAMEORIGIN
< X-Content-Type-Options: nosniff
< Content-Security-Policy: default-src 'self' https://www.taler.net/dist/; img-src 'self' https://unpkg.com/ https://secure.gravatar.com/ https://git.taler.net/ data: blob:; script-src 'self' 'unsafe-inline' 'unsafe-eval' https://www.taler.net/dist/js/; style-src 'self' 'unsafe-inline' https://www.taler.net/dist/css/; connect-src 'self' wss://buildbot.taler.net; object-src 'self' blob:; font-src 'self' data:
< Referrer-Policy: same-origin
< 
* Connection #2 to host exchange.demo.taler.net left intact
2023-11-13T18:32:24.509490+0100 taler-merchant-httpd-364050 INFO Received keys from URL `https://exchange.demo.taler.net/keys' with status 200 and expiration Mon Jan 01 00:00:00 2024.
2023-11-13T18:32:24.509500+0100 taler-merchant-httpd-364050 WARNING Parsing /keys failed for `currency_specification' (9)
2023-11-13T18:32:24.509504+0100 taler-merchant-httpd-364050 ERROR Assertion failed at exchange_api_handle.c:924.
2023-11-13T18:32:24.509507+0100 taler-merchant-httpd-364050 ERROR Could not decode /keys response
2023-11-13T18:32:24.509513+0100 taler-merchant-httpd-364050 WARNING Failed to fetch /keys from `https://exchange.demo.taler.net/'; retrying in 621 ms
2023-11-13T18:32:24.509527+0100 taler-merchant-httpd-364050 INFO HTTP request for `https://exchange.demo.taler.net/keys' finished with 200 after 96 ms
2023-11-13T18:32:25.131447+0100 taler-merchant-httpd-364050 INFO Fetching /keys from exchange https://exchange.demo.taler.net/ in retry_exchange()
* Found bundle for host: 0xe7fc90 [serially]
* Can not multiplex, even if we wanted to
* Re-using existing connection #2 with host exchange.demo.taler.net
> GET /keys HTTP/1.1
Host: exchange.demo.taler.net
Accept: */*
Accept-Encoding: deflate, gzip
Content-Type: application/json

< HTTP/1.1 200 OK
< Server: nginx
< Date: Mon, 13 Nov 2023 17:32:22 GMT
< Content-Type: application/json
< Content-Length: 3636
< Connection: keep-alive
< Content-Encoding: deflate
< Access-Control-Allow-Origin: *
< Access-Control-Expose-Headers: *
< Last-Modified: Mon, 13 Nov 2023 16:53:18 GMT
< Expires: Mon, 01 Jan 2024 00:00:00 GMT
2023-11-13T18:32:25.194949+0100 taler-merchant-httpd-364050 INFO Found Expires header `Mon, 01 Jan 2024 00:00:00 GMT
'
< Vary: Accept-Encoding
< Cache-Control: public,max-age=3600
< ETag: 6RVT19R1YJ7W25MZ929CH6GVPEW8H46DRGVK3WW794YZ2E7C30VB3QJ6ZY975APQH5K491HRTEF1BWK1AG1GZJJ3A0BATFKDSGMF8Z0
< Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
< X-XSS-Protection: 1; mode=block
< X-Frame-Options: SAMEORIGIN
< X-Content-Type-Options: nosniff
< Content-Security-Policy: default-src 'self' https://www.taler.net/dist/; img-src 'self' https://unpkg.com/ https://secure.gravatar.com/ https://git.taler.net/ data: blob:; script-src 'self' 'unsafe-inline' 'unsafe-eval' https://www.taler.net/dist/js/; style-src 'self' 'unsafe-inline' https://www.taler.net/dist/css/; connect-src 'self' wss://buildbot.taler.net; object-src 'self' blob:; font-src 'self' data:
< Referrer-Policy: same-origin
< 
* Connection #2 to host exchange.demo.taler.net left intact
2023-11-13T18:32:25.195105+0100 taler-merchant-httpd-364050 INFO Received keys from URL `https://exchange.demo.taler.net/keys' with status 200 and expiration Mon Jan 01 00:00:00 2024.
2023-11-13T18:32:25.195118+0100 taler-merchant-httpd-364050 WARNING Parsing /keys failed for `currency_specification' (9)
2023-11-13T18:32:25.195122+0100 taler-merchant-httpd-364050 ERROR Assertion failed at exchange_api_handle.c:924.
2023-11-13T18:32:25.195126+0100 taler-merchant-httpd-364050 ERROR Could not decode /keys response
2023-11-13T18:32:25.195132+0100 taler-merchant-httpd-364050 WARNING Failed to fetch /keys from `https://exchange.demo.taler.net/'; retrying in 2982 ms
2023-11-13T18:32:25.195142+0100 taler-merchant-httpd-364050 INFO HTTP request for `https://exchange.demo.taler.net/keys' finished with 200 after 63 ms
2023-11-13T18:32:25.257912+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Handling request (POST) for URL '/private/orders'
2023-11-13T18:32:25.257939+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Processing order in phase 0
2023-11-13T18:32:25.258678+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Processing order in phase 1
2023-11-13T18:32:25.258687+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Processing order in phase 2
2023-11-13T18:32:25.258693+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Processing order in phase 3
2023-11-13T18:32:25.258712+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Assigning order ID `2023.317-02H0G9EAA2214' server-side
2023-11-13T18:32:25.258721+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Refund delay is zero, no refunds are possible for this order
2023-11-13T18:32:25.258747+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Processing order in phase 4
2023-11-13T18:32:25.258751+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Trying to find chosen exchange `https://exchange.demo.taler.net/'
2023-11-13T18:32:25.258755+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Already waiting for `https://exchange.demo.taler.net/keys' for a while, failing query instantly
2023-11-13T18:32:25.258760+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Trying to find chosen exchange `http://localhost:8081/'
2023-11-13T18:32:25.258765+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO The exchange `http://localhost:8081/' is ready
2023-11-13T18:32:25.258770+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Trying to find chosen exchange `http://localhost:8281/'
2023-11-13T18:32:25.258777+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Next http://localhost:8281/keys (1) request scheduled for Mon Nov 13 18:34:23 2023
2023-11-13T18:32:25.258781+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Still trying to re-load /keys
2023-11-13T18:32:25.258790+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Returning key data for https://exchange.demo.taler.net/ instantly
2023-11-13T18:32:25.258794+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Processing find operations for `https://exchange.demo.taler.net/' (-1)
2023-11-13T18:32:25.258799+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) WARNING Failed to download https://exchange.demo.taler.net/keys
2023-11-13T18:32:25.258803+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Returning key data for http://localhost:8081/ instantly
2023-11-13T18:32:25.258808+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Processing find operations for `http://localhost:8081/' (2)
2023-11-13T18:32:25.258812+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Got response for http://localhost:8081/keys
2023-11-13T18:32:25.258833+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Updated STEFAN-based fee to TESTKUDOS:5
2023-11-13T18:32:25.258839+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Exchange http://localhost:8081/ evaluated at 1
2023-11-13T18:32:28.181075+0100 taler-merchant-httpd-364050 INFO Fetching /keys from exchange https://exchange.demo.taler.net/ in retry_exchange()
* Found bundle for host: 0xe7fc90 [serially]
* Can not multiplex, even if we wanted to
* Re-using existing connection #2 with host exchange.demo.taler.net
> GET /keys HTTP/1.1
Host: exchange.demo.taler.net
Accept: */*
Accept-Encoding: deflate, gzip
Content-Type: application/json

< HTTP/1.1 200 OK
< Server: nginx
< Date: Mon, 13 Nov 2023 17:32:25 GMT
< Content-Type: application/json
< Content-Length: 3636
< Connection: keep-alive
< Content-Encoding: deflate
< Access-Control-Allow-Origin: *
< Access-Control-Expose-Headers: *
< Last-Modified: Mon, 13 Nov 2023 16:53:18 GMT
< Expires: Mon, 01 Jan 2024 00:00:00 GMT
2023-11-13T18:32:28.206301+0100 taler-merchant-httpd-364050 INFO Found Expires header `Mon, 01 Jan 2024 00:00:00 GMT
'
< Vary: Accept-Encoding
< Cache-Control: public,max-age=3600
< ETag: 6RVT19R1YJ7W25MZ929CH6GVPEW8H46DRGVK3WW794YZ2E7C30VB3QJ6ZY975APQH5K491HRTEF1BWK1AG1GZJJ3A0BATFKDSGMF8Z0
< Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
< X-XSS-Protection: 1; mode=block
< X-Frame-Options: SAMEORIGIN
< X-Content-Type-Options: nosniff
< Content-Security-Policy: default-src 'self' https://www.taler.net/dist/; img-src 'self' https://unpkg.com/ https://secure.gravatar.com/ https://git.taler.net/ data: blob:; script-src 'self' 'unsafe-inline' 'unsafe-eval' https://www.taler.net/dist/js/; style-src 'self' 'unsafe-inline' https://www.taler.net/dist/css/; connect-src 'self' wss://buildbot.taler.net; object-src 'self' blob:; font-src 'self' data:
< Referrer-Policy: same-origin
< 
* Connection #2 to host exchange.demo.taler.net left intact
2023-11-13T18:32:28.206476+0100 taler-merchant-httpd-364050 INFO Received keys from URL `https://exchange.demo.taler.net/keys' with status 200 and expiration Mon Jan 01 00:00:00 2024.
2023-11-13T18:32:28.206490+0100 taler-merchant-httpd-364050 WARNING Parsing /keys failed for `currency_specification' (9)
2023-11-13T18:32:28.206494+0100 taler-merchant-httpd-364050 ERROR Assertion failed at exchange_api_handle.c:924.
2023-11-13T18:32:28.206498+0100 taler-merchant-httpd-364050 ERROR Could not decode /keys response
2023-11-13T18:32:28.206505+0100 taler-merchant-httpd-364050 WARNING Failed to fetch /keys from `https://exchange.demo.taler.net/'; retrying in 17 s
2023-11-13T18:32:28.206523+0100 taler-merchant-httpd-364050 INFO HTTP request for `https://exchange.demo.taler.net/keys' finished with 200 after 25 ms
2023-11-13T18:32:45.425877+0100 taler-merchant-httpd-364050 INFO Fetching /keys from exchange https://exchange.demo.taler.net/ in retry_exchange()
* Found bundle for host: 0xe7fc90 [serially]
* Can not multiplex, even if we wanted to
* Re-using existing connection #2 with host exchange.demo.taler.net
> GET /keys HTTP/1.1
Host: exchange.demo.taler.net
Accept: */*
Accept-Encoding: deflate, gzip
Content-Type: application/json

< HTTP/1.1 200 OK
< Server: nginx
< Date: Mon, 13 Nov 2023 17:32:42 GMT
< Content-Type: application/json
< Content-Length: 3636
< Connection: keep-alive
< Content-Encoding: deflate
< Access-Control-Allow-Origin: *
< Access-Control-Expose-Headers: *
< Last-Modified: Mon, 13 Nov 2023 16:53:18 GMT
< Expires: Mon, 01 Jan 2024 00:00:00 GMT
2023-11-13T18:32:45.468950+0100 taler-merchant-httpd-364050 INFO Found Expires header `Mon, 01 Jan 2024 00:00:00 GMT
'
< Vary: Accept-Encoding
< Cache-Control: public,max-age=3600
< ETag: 6RVT19R1YJ7W25MZ929CH6GVPEW8H46DRGVK3WW794YZ2E7C30VB3QJ6ZY975APQH5K491HRTEF1BWK1AG1GZJJ3A0BATFKDSGMF8Z0
< Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
< X-XSS-Protection: 1; mode=block
< X-Frame-Options: SAMEORIGIN
< X-Content-Type-Options: nosniff
< Content-Security-Policy: default-src 'self' https://www.taler.net/dist/; img-src 'self' https://unpkg.com/ https://secure.gravatar.com/ https://git.taler.net/ data: blob:; script-src 'self' 'unsafe-inline' 'unsafe-eval' https://www.taler.net/dist/js/; style-src 'self' 'unsafe-inline' https://www.taler.net/dist/css/; connect-src 'self' wss://buildbot.taler.net; object-src 'self' blob:; font-src 'self' data:
< Referrer-Policy: same-origin
< 
* Connection #2 to host exchange.demo.taler.net left intact
2023-11-13T18:32:45.469155+0100 taler-merchant-httpd-364050 INFO Received keys from URL `https://exchange.demo.taler.net/keys' with status 200 and expiration Mon Jan 01 00:00:00 2024.
2023-11-13T18:32:45.469171+0100 taler-merchant-httpd-364050 WARNING Parsing /keys failed for `currency_specification' (9)
2023-11-13T18:32:45.469177+0100 taler-merchant-httpd-364050 ERROR Assertion failed at exchange_api_handle.c:924.
2023-11-13T18:32:45.469182+0100 taler-merchant-httpd-364050 ERROR Could not decode /keys response
2023-11-13T18:32:45.469190+0100 taler-merchant-httpd-364050 WARNING Failed to fetch /keys from `https://exchange.demo.taler.net/'; retrying in 1 m
2023-11-13T18:32:45.469205+0100 taler-merchant-httpd-364050 INFO HTTP request for `https://exchange.demo.taler.net/keys' finished with 200 after 43 ms
2023-11-13T18:32:46.869210+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Request for `/private/orders' completed with HTTP status 0 (3)
2023-11-13T18:32:46.869287+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Executing PQ command `UNLISTEN XN0RW6KT8Y9MK75YM85SC7GTA6SC5W91FXWDQP0ZB42GY3E52DZH0'
2023-11-13T18:32:46.869431+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Executing PQ command `UNLISTEN XW9K15VBEKGDMCMN31SKH75KVXND1GTW5MW7WME4CMPQ0X9ECWTR0'
2023-11-13T18:32:46.869472+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Stopping PQ event scheduler job
2023-11-13T18:32:46.869483+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Releasing trusted exchange https://exchange.demo.taler.net/ (-1)
2023-11-13T18:32:46.869493+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Releasing trusted exchange http://localhost:8081/ (2)
2023-11-13T18:32:46.869518+0100 taler-merchant-httpd-364050(MQB0VZC6FJRK5EW0YT7DJGN49G) INFO Releasing trusted exchange http://localhost:8281/ (1)
* Closing connection 0
merchant-testmerchant-1-stderr.log (39,871 bytes)   

Florian Dold

2023-11-13 18:46

manager   ~0020637

What's also odd is that the merchant is talking to the demo exchange. Is there a way to disable the demo.taler.net exchange in the merchant config?

Christian Grothoff

2023-11-13 20:19

manager   ~0020638

[merchant-exchange-kudos]
DISABLE = YES

will disable KUDOS.

Florian Dold

2023-11-14 13:45

manager   ~0020639

I've confirmed that both exchanges are added to the contract terms by the merchant when they work, and that only one exchange is added when the other can't be contacted.

Issue History

Date Modified Username Field Change
2023-10-18 20:44 Florian Dold New Issue
2023-10-18 20:44 Florian Dold Status new => assigned
2023-10-18 20:44 Florian Dold Assigned To => Christian Grothoff
2023-10-29 16:06 Christian Grothoff Note Added: 0020610
2023-10-29 16:06 Christian Grothoff Assigned To Christian Grothoff => Florian Dold
2023-10-29 16:06 Christian Grothoff Status assigned => feedback
2023-10-29 16:06 Christian Grothoff Note Added: 0020611
2023-11-13 18:41 Florian Dold Note Added: 0020636
2023-11-13 18:41 Florian Dold File Added: merchant-testmerchant-1-stderr.log
2023-11-13 18:41 Florian Dold Assigned To Florian Dold => Christian Grothoff
2023-11-13 18:46 Florian Dold Note Added: 0020637
2023-11-13 18:46 Florian Dold Status feedback => assigned
2023-11-13 20:19 Christian Grothoff Note Added: 0020638
2023-11-13 20:29 Florian Dold Assigned To Christian Grothoff => Florian Dold
2023-11-14 13:45 Florian Dold Note Added: 0020639
2023-11-14 13:50 Florian Dold Status assigned => resolved
2023-11-14 13:50 Florian Dold Resolution open => fixed
2023-11-29 01:28 Christian Grothoff Target Version 0.9.4 => 0.9.3
2023-11-29 01:29 Christian Grothoff Fixed in Version => 0.9.3
2023-11-29 01:30 Christian Grothoff Status resolved => closed
2024-01-12 14:04 Christian Grothoff Category merchant backend API (C) => mechant backend