View Issue Details

IDProjectCategoryView StatusLast Update
0005330Talermechant backendpublic2019-12-20 19:12
ReporterMarcello Stanisci Assigned ToMarcello Stanisci  
PrioritynormalSeverityminorReproducibilitysometimes
Status closedResolutionfixed 
Product Versiongit (master) 
Target Version0.6Fixed in Version0.6 
Summary0005330: Sporadic tests failures
DescriptionThe "lib" test cases showed those failures in a quite random way.

1:

May 22 09:10:02-146177 test-merchant-api-new-4401 DEBUG Running command `run-aggregator-11'
May 22 09:10:02-164984 taler-exchange-aggregator-4517 ERROR Assertion failed at taler-exchange-aggregator.c:639

2:

May 22 15:31:27-183633 test-merchant-api-7162 INFO Interpreter runs command 84/pay-abort-11(8)
May 22 15:31:27-200353 taler-merchant-httpd-7187 ERROR Unknown contract: NQRDS3SR (merchant_pub: S16KZC9V), no refund possible
May 22 15:31:27-200485 test-merchant-api-7162 INFO /pay completed with response code 200
May 22 15:31:27-200507 test-merchant-api-7162 INFO Interpreter runs command 85/pay-abort-refund-11(9)
May 22 15:31:27-200515 test-merchant-api-7162 ERROR Assertion failed at test_merchant_api.c:3694.
TagsNo tags attached.

Activities

Marcello Stanisci

2018-05-23 10:13

viewer   ~0012952

Same failure on the abort CMD from the _new test case.

May 23 10:11:47-224319 test-merchant-api-new-11784 DEBUG Running command `pay-abort-11'
May 23 10:11:47-238310 taler-merchant-httpd-11810 ERROR Unknown contract: K2X3AQMB (merchant_pub: PQ436RXG), no refund possible
May 23 10:11:47-238435 test-merchant-api-new-11784 INFO /pay completed with response code 200
May 23 10:11:47-238459 test-merchant-api-new-11784 DEBUG Running command `pay-abort-refund-11'
May 23 10:11:47-238468 test-merchant-api-new-11784 ERROR Assertion failed at testing_api_cmd_pay.c:1481.
May 23 10:11:47-238472 test-merchant-api-new-11784 ERROR Failed at command `pay-abort-refund-11'
May 23 10:11:47-238479 test-merchant-api-new-11784 INFO Executing shutdown at `pay-abort-refund-11'

Marcello Stanisci

2018-05-23 10:49

viewer   ~0012953

The pay-abort CMD causes fails at the twisted test case as well.

May 23 10:30:02-155331 test-merchant-api-twisted-13874 DEBUG Running command `pay-abort-4'
May 23 10:30:02-171794 test-merchant-api-twisted-13874 INFO /pay completed with response code 200
May 23 10:30:02-175343 test-merchant-api-twisted-13874 ERROR Unexpected response code 200 (0) to command pay-abort-4
May 23 10:30:02-175352 test-merchant-api-twisted-13874 ERROR Assertion failed at testing_api_cmd_pay.c:652.
May 23 10:30:02-175357 test-merchant-api-twisted-13874 ERROR Failed at command `pay-abort-4'
May 23 10:30:02-175374 test-merchant-api-twisted-13874 INFO Executing shutdown at `pay-abort-4'

Marcello Stanisci

2018-05-23 16:53

viewer  

test_merchant_api.log (157,518 bytes)   
May 23 16:43:54-082365 test-merchant-api-13830 INFO Found instances `default tor'
May 23 16:43:58-422616 test-merchant-api-13830 INFO Waiting for taler-exchange-httpd to be ready
.
May 23 16:43:59-429842 test-merchant-api-13830 INFO Waiting for taler-merchant-httpd to be ready
.May 23 16:43:59-434638 taler-merchant-httpd-13855 INFO Starting taler-merchant-httpd
May 23 16:43:59-434729 taler-merchant-httpd-13855 INFO Loaded key data of auditor `European Central Bank' (8C78B8J9)
May 23 16:43:59-434762 taler-merchant-httpd-13855 DEBUG Extracted token: nulltip
May 23 16:43:59-437074 taler-merchant-httpd-13855 DEBUG Extracted token: dtip
May 23 16:43:59-439278 taler-merchant-httpd-13855 DEBUG Extracted token: tip
May 23 16:43:59-441469 taler-merchant-httpd-13855 DEBUG Extracted token: tor
May 23 16:43:59-443647 taler-merchant-httpd-13855 DEBUG Extracted token: default
May 23 16:43:59-450638 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:00-438025 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:00-438070 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/'
May 23 16:44:00-438521 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:00-438757 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task

May 23 16:44:00-438860 test-merchant-api-13830 DEBUG Interpreter initializing
May 23 16:44:00-438947 test-merchant-api-13830 DEBUG Requesting keys with URL `http://localhost:8081/keys'.
May 23 16:44:00-442446 test-merchant-api-13830 DEBUG Received keys from URL `http://localhost:8081/keys' with status 200.
May 23 16:44:00-632225 test-merchant-api-13830 DEBUG Read 2 signing keys
May 23 16:44:00-632239 test-merchant-api-13830 DEBUG Read 20 denomination keys
May 23 16:44:00-632243 test-merchant-api-13830 DEBUG Certificate callback invoked, starting interpreter
May 23 16:44:00-632274 test-merchant-api-13830 INFO Interpreter runs command 0/create-reserve-1(2)
May 23 16:44:00-638919 test-merchant-api-13830 DEBUG Making transfer from 62 to 2 over EUR:10.02 and subject 3JXNY3T7VMMR5SH67QBB3YS902X2KFPJ9B1MPAYP73T7YG8RQJSG
May 23 16:44:00-638935 test-merchant-api-13830 INFO Receiving incoming wire transfer: 62->2 from http://localhost:8081/
May 23 16:44:00-638994 test-merchant-api-13830 INFO Interpreter runs command 1/wirewatch-1(11)
May 23 16:44:00-652348 test-merchant-api-13830 INFO Client asked for up to 1024 results of type credit for account 2 starting at (null)
May 23 16:44:00-652374 test-merchant-api-13830 INFO Found transaction over EUR:10.02 from 62 to 2
May 23 16:44:00-671645 test-merchant-api-13830 INFO Interpreter runs command 2/check_bank_transfer-1(12)
May 23 16:44:00-671679 test-merchant-api-13830 INFO Interpreter runs command 3/withdraw-coin-1(4)
May 23 16:44:00-705008 test-merchant-api-13830 INFO Interpreter runs command 4/withdraw-coin-2(4)
May 23 16:44:00-729836 test-merchant-api-13830 INFO Interpreter runs command 5/withdraw-status-1(3)
May 23 16:44:00-740786 test-merchant-api-13830 INFO Interpreter runs command 6/create-proposal-1(5)
May 23 16:44:00-742165 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:00-742188 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:00-742200 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:00-742205 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:00-742209 taler-merchant-httpd-13855 DEBUG Will parse: {"order":{"max_fee":{"currency":"EUR","value":0,"fraction":50000000},"order_id":"1","refund_deadline":"/Date(0)/","pay_deadline":"/Date(99999999999)/","amount":{"currency":"EUR","value":5,"fraction":0},"summary":"merchant-lib testcase","fulfillment_url":"https://example.com/","products":[{"description":"ice cream","value":"{EUR:5}"}],"merchant":{"instance":"default"}}}
May 23 16:44:00-742214 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 371
May 23 16:44:00-742221 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:00-742225 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:00-742235 taler-merchant-httpd-13855 DEBUG About to parse: {"order":{"max_fee":{"currency":"EUR","value":0,"fraction":50000000},"order_id":"1","refund_deadline":"/Date(0)/","pay_deadline":"/Date(99999999999)/","amount":{"currency":"EUR","value":5,"fraction":0},"summary":"merchant-lib testcase","fulfillment_url":"https://example.com/","products":[{"description":"ice cream","value":"{EUR:5}"}],"merchant":{"instance":"default"}}}
May 23 16:44:00-742278 taler-merchant-httpd-13855 DEBUG Giving 'default' instance
May 23 16:44:00-742290 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:00-742307 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:00-742315 taler-merchant-httpd-13855 DEBUG Inserting order '1' for instance 'default'
May 23 16:44:00-742332 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1', merchant_pub: 'PQ436RXG'.
May 23 16:44:00-742634 taler-merchant-httpd-13855 DEBUG inserting order: order_id: 1, merchant_pub: PQ436RXG.
May 23 16:44:00-745909 taler-merchant-httpd-13855 INFO Finished handling request for `/order' with status 0
May 23 16:44:00-745928 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:00-745983 test-merchant-api-13830 INFO looking up proposal from http://localhost:8080/public/proposal?order_id=1&instance=default&nonce=HMRBG5VDFYNZ0W364D2HQYQ4QRDF4QFTXSN5TQRGE739ZB5091FG
May 23 16:44:00-746080 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/public/proposal'
May 23 16:44:00-746115 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:00-746128 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1', merchant_pub: 'PQ436RXG'.
May 23 16:44:00-746347 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1', merchant_pub: 'PQ436RXG'.
May 23 16:44:00-746493 taler-merchant-httpd-13855 DEBUG inserting contract_terms: order_id: 1, merchant_pub: PQ436RXG, h_contract_terms: 9D95Y8QE.
May 23 16:44:00-759746 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:00-759869 test-merchant-api-13830 INFO Interpreter runs command 7/check-payment-1(21)
May 23 16:44:00-759897 test-merchant-api-13830 INFO checking payment from http://localhost:8080/check-payment?instance=default&order_id=1
May 23 16:44:00-759984 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/check-payment'
May 23 16:44:00-760013 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:00-760024 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1', merchant_pub: 'PQ436RXG'.
May 23 16:44:00-760307 taler-merchant-httpd-13855 DEBUG not paid yet
May 23 16:44:00-760361 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:00-760452 test-merchant-api-13830 INFO check payment: expected paid: check-payment-1: 0
May 23 16:44:00-760465 test-merchant-api-13830 INFO check payment: paid: 0
May 23 16:44:00-760471 test-merchant-api-13830 INFO check payment: url: https://localhost:8080/public/trigger-pay?contract_url=https%3A%2F%2Flocalhost%3A8080%2Fpublic%2Fproposal%3Finstance%3Ddefault%26order_id%3D1&h_contract_terms=9D95Y8QEG6CMF3KVWP9HPGW688NWYP341EH8B3N0TWWX2EP3EPFZNDWEHNPVKAM1HDYC4EB3X40CGNZX81DENZR3YPNN55549W3QMD0
May 23 16:44:00-760482 test-merchant-api-13830 INFO Interpreter runs command 8/deposit-simple(6)
May 23 16:44:00-762519 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:00-762527 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:00-768597 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:00-768632 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:00-768638 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:00-768646 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:00-768666 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:00-768815 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:00-768828 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:00-768836 taler-merchant-httpd-13855 DEBUG Will parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"0RB08NMY6KNVXB4B5J7HMRWRMHBN8KHRTXDMM0QPZNDJQ69K4S4J0KJ8H07B0CKBB2JRW7WG22HJ6T8EWZM5RK1H8HKQW7MXHVZ240G"}],"order_id":"1","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:00-768841 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 1344
May 23 16:44:00-768846 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:00-768850 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:00-768853 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:00-768861 taler-merchant-httpd-13855 DEBUG About to parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"0RB08NMY6KNVXB4B5J7HMRWRMHBN8KHRTXDMM0QPZNDJQ69K4S4J0KJ8H07B0CKBB2JRW7WG22HJ6T8EWZM5RK1H8HKQW7MXHVZ240G"}],"order_id":"1","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:00-768895 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1', merchant_pub: 'PQ436RXG'.
May 23 16:44:00-769058 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:00-769072 taler-merchant-httpd-13855 INFO /pay: picked instance default
May 23 16:44:00-769121 taler-merchant-httpd-13855 DEBUG Suspending /pay handling while working with the exchange
May 23 16:44:00-769130 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:00-769180 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms '9D95Y8QE'
May 23 16:44:00-769388 taler-merchant-httpd-13855 DEBUG Looking for refund 9D95Y8QE + PQ436RXG
May 23 16:44:00-769545 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:00-769594 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:00-769604 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is new
May 23 16:44:00-769609 taler-merchant-httpd-13855 DEBUG Do not have current key data. Will request /keys now
May 23 16:44:00-769617 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:00-769627 taler-merchant-httpd-13855 DEBUG Connecting to exchange exchange http://localhost:8081/ in retry_exchange
May 23 16:44:00-769642 taler-merchant-httpd-13855 DEBUG Requesting keys with URL `http://localhost:8081/keys'.
May 23 16:44:00-771540 taler-merchant-httpd-13855 DEBUG Received keys from URL `http://localhost:8081/keys' with status 200.
May 23 16:44:00-935110 taler-merchant-httpd-13855 DEBUG Got key data, but do not have current wire data. Will request /wire now
May 23 16:44:00-939002 taler-merchant-httpd-13855 DEBUG Storing wire fee for `HGYF3P1M' and method `x-taler-bank' at Mon Jan 01 00:00:00 2018 in DB; the fee is EUR:0.01
May 23 16:44:00-939010 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:00-939068 taler-merchant-httpd-13855 INFO Storing wire fee for HGYF3P1M starting at Mon Jan 01 00:00:00 2018 of EUR:0.01
May 23 16:44:00-939283 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:00-946113 taler-merchant-httpd-13855 DEBUG Storing wire fee for `HGYF3P1M' and method `x-taler-bank' at Tue Jan 01 00:00:00 2019 in DB; the fee is EUR:0.01
May 23 16:44:00-946123 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:00-946160 taler-merchant-httpd-13855 INFO Storing wire fee for HGYF3P1M starting at Tue Jan 01 00:00:00 2019 of EUR:0.01
May 23 16:44:00-946251 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:00-954340 taler-merchant-httpd-13855 DEBUG Storing wire fee for `HGYF3P1M' and method `x-taler-bank' at Wed Jan 01 00:00:00 2020 in DB; the fee is EUR:0.01
May 23 16:44:00-954349 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:00-954382 taler-merchant-httpd-13855 INFO Storing wire fee for HGYF3P1M starting at Wed Jan 01 00:00:00 2020 of EUR:0.01
May 23 16:44:00-954465 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:00-962671 taler-merchant-httpd-13855 DEBUG Storing wire fee for `HGYF3P1M' and method `x-taler-bank' at Fri Jan 01 00:00:00 2021 in DB; the fee is EUR:0.01
May 23 16:44:00-962680 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:00-962713 taler-merchant-httpd-13855 INFO Storing wire fee for HGYF3P1M starting at Fri Jan 01 00:00:00 2021 of EUR:0.01
May 23 16:44:00-962798 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:00-971033 taler-merchant-httpd-13855 DEBUG Found transaction data for proposal `9D95Y8QE' of merchant `PQ436RXG', initiating deposits
May 23 16:44:00-971067 taler-merchant-httpd-13855 DEBUG Timing for this payment, wire_deadline: 1527086640000000, refund_deadline: 0
May 23 16:44:00-974826 taler-merchant-httpd-13855 DEBUG URL for deposit: `http://localhost:8081/deposit'
May 23 16:44:00-997832 taler-merchant-httpd-13855 DEBUG Storing successful payment for h_contract_terms `9D95Y8QE' and merchant `PQ436RXG'
May 23 16:44:00-997859 taler-merchant-httpd-13855 DEBUG Storing payment for h_contract_terms `9D95Y8QE', coin_pub: `ZGGH7V4V', amount_with_fee: EUR:5
May 23 16:44:00-997866 taler-merchant-httpd-13855 DEBUG Merchant pub is `PQ436RXG'
May 23 16:44:01-004361 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-004624 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms '9D95Y8QE'
May 23 16:44:01-005314 taler-merchant-httpd-13855 DEBUG Looking for refund 9D95Y8QE + PQ436RXG
May 23 16:44:01-005786 taler-merchant-httpd-13855 INFO Subtracting total refunds from paid amount: EUR:0
May 23 16:44:01-005856 taler-merchant-httpd-13855 DEBUG Marking proposal paid, h_contract_terms: '9D95Y8QE', merchant_pub: 'PQ436RXG'
May 23 16:44:01-006500 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-012737 taler-merchant-httpd-13855 DEBUG Looking for refund 9D95Y8QE + PQ436RXG
May 23 16:44:01-035720 taler-merchant-httpd-13855 DEBUG Resuming /pay handling as exchange interaction is done (200)
May 23 16:44:01-035767 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-035782 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-035796 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /pay (OK).
May 23 16:44:01-035821 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-035896 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-035943 taler-merchant-httpd-13855 INFO Finished handling request for `/public/pay' with status 0
May 23 16:44:01-035978 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-036079 test-merchant-api-13830 INFO /pay completed with response code 200
May 23 16:44:01-047246 test-merchant-api-13830 INFO Interpreter runs command 9/check-payment-2(21)
May 23 16:44:01-047293 test-merchant-api-13830 INFO checking payment from http://localhost:8080/check-payment?instance=default&order_id=1
May 23 16:44:01-047442 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/check-payment'
May 23 16:44:01-047483 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-047509 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-048243 taler-merchant-httpd-13855 DEBUG Looking for refund 9D95Y8QE + PQ436RXG
May 23 16:44:01-048578 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-048747 test-merchant-api-13830 INFO check payment: expected paid: check-payment-2: 1
May 23 16:44:01-048778 test-merchant-api-13830 INFO check payment: paid: 1
May 23 16:44:01-048788 test-merchant-api-13830 INFO check payment: url: (null)
May 23 16:44:01-048819 test-merchant-api-13830 INFO Interpreter runs command 10/pay-abort-2(8)
May 23 16:44:01-054086 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:01-054109 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:01-069750 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-069777 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-069788 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-069805 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-069844 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-069984 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-070010 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-070027 taler-merchant-httpd-13855 DEBUG Will parse: {"mode":"abort-refund","coins":[{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"0RB08NMY6KNVXB4B5J7HMRWRMHBN8KHRTXDMM0QPZNDJQ69K4S4J0KJ8H07B0CKBB2JRW7WG22HJ6T8EWZM5RK1H8HKQW7MXHVZ240G"}],"order_id":"1","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:01-070045 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 1353
May 23 16:44:01-070056 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-070063 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-070070 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-070084 taler-merchant-httpd-13855 DEBUG About to parse: {"mode":"abort-refund","coins":[{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"0RB08NMY6KNVXB4B5J7HMRWRMHBN8KHRTXDMM0QPZNDJQ69K4S4J0KJ8H07B0CKBB2JRW7WG22HJ6T8EWZM5RK1H8HKQW7MXHVZ240G"}],"order_id":"1","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:01-070145 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-070452 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-070473 taler-merchant-httpd-13855 INFO /pay: picked instance default
May 23 16:44:01-070542 taler-merchant-httpd-13855 DEBUG Suspending /pay handling while working with the exchange
May 23 16:44:01-070554 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-070625 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms '9D95Y8QE'
May 23 16:44:01-070858 taler-merchant-httpd-13855 DEBUG Coin (ZGGH7V4V) already found in our DB.
May 23 16:44:01-070886 taler-merchant-httpd-13855 DEBUG Looking for refund 9D95Y8QE + PQ436RXG
May 23 16:44:01-071231 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-071325 taler-merchant-httpd-13855 DEBUG Resuming /pay handling as exchange interaction is done (403)
May 23 16:44:01-071350 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-071359 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-071367 taler-merchant-httpd-13855 DEBUG Queueing response (403) for /pay (OK).
May 23 16:44:01-071383 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-071423 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-071450 taler-merchant-httpd-13855 INFO Finished handling request for `/public/pay' with status 0
May 23 16:44:01-071472 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-071499 test-merchant-api-13830 INFO /pay completed with response code 403
May 23 16:44:01-071541 test-merchant-api-13830 INFO Interpreter runs command 11/replay-simple(6)
May 23 16:44:01-075349 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:01-075362 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:01-083938 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-083956 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-083963 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-083976 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-084002 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-084164 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-084183 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-084194 taler-merchant-httpd-13855 DEBUG Will parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"0RB08NMY6KNVXB4B5J7HMRWRMHBN8KHRTXDMM0QPZNDJQ69K4S4J0KJ8H07B0CKBB2JRW7WG22HJ6T8EWZM5RK1H8HKQW7MXHVZ240G"}],"order_id":"1","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:01-084200 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 1344
May 23 16:44:01-084207 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-084212 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-084216 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-084226 taler-merchant-httpd-13855 DEBUG About to parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"0RB08NMY6KNVXB4B5J7HMRWRMHBN8KHRTXDMM0QPZNDJQ69K4S4J0KJ8H07B0CKBB2JRW7WG22HJ6T8EWZM5RK1H8HKQW7MXHVZ240G"}],"order_id":"1","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:01-084266 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-084475 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-084489 taler-merchant-httpd-13855 INFO /pay: picked instance default
May 23 16:44:01-084542 taler-merchant-httpd-13855 DEBUG Suspending /pay handling while working with the exchange
May 23 16:44:01-084551 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-084600 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms '9D95Y8QE'
May 23 16:44:01-084759 taler-merchant-httpd-13855 DEBUG Coin (ZGGH7V4V) already found in our DB.
May 23 16:44:01-084772 taler-merchant-httpd-13855 DEBUG Looking for refund 9D95Y8QE + PQ436RXG
May 23 16:44:01-084856 taler-merchant-httpd-13855 INFO Subtracting total refunds from paid amount: EUR:0
May 23 16:44:01-084868 taler-merchant-httpd-13855 DEBUG Marking proposal paid, h_contract_terms: '9D95Y8QE', merchant_pub: 'PQ436RXG'
May 23 16:44:01-085002 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-096075 taler-merchant-httpd-13855 DEBUG Looking for refund 9D95Y8QE + PQ436RXG
May 23 16:44:01-102724 taler-merchant-httpd-13855 DEBUG Resuming /pay handling as exchange interaction is done (200)
May 23 16:44:01-102744 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-102749 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-102754 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /pay (OK).
May 23 16:44:01-102766 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-102794 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-102812 taler-merchant-httpd-13855 INFO Finished handling request for `/public/pay' with status 0
May 23 16:44:01-102824 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-102881 test-merchant-api-13830 INFO /pay completed with response code 200
May 23 16:44:01-107664 test-merchant-api-13830 INFO Interpreter runs command 12/create-proposal-2(5)
May 23 16:44:01-107828 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:01-107844 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-107854 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:01-107860 taler-merchant-httpd-13855 DEBUG Will parse: {"order":{"max_fee":{"currency":"EUR","value":0,"fraction":50000000},"order_id":"2","refund_deadline":"/Date(0)/","pay_deadline":"/Date(9999999999)/","amount":{"currency":"EUR","value":5,"fraction":0},"summary":"useful product","fulfillment_url":"https://example.com/","products":[{"description":"ice cream","value":"{EUR:5}"}],"merchant":{"instance":"default"}}}
May 23 16:44:01-107865 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 363
May 23 16:44:01-107870 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:01-107873 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-107878 taler-merchant-httpd-13855 DEBUG About to parse: {"order":{"max_fee":{"currency":"EUR","value":0,"fraction":50000000},"order_id":"2","refund_deadline":"/Date(0)/","pay_deadline":"/Date(9999999999)/","amount":{"currency":"EUR","value":5,"fraction":0},"summary":"useful product","fulfillment_url":"https://example.com/","products":[{"description":"ice cream","value":"{EUR:5}"}],"merchant":{"instance":"default"}}}
May 23 16:44:01-107902 taler-merchant-httpd-13855 DEBUG Giving 'default' instance
May 23 16:44:01-107909 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-107919 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-107927 taler-merchant-httpd-13855 DEBUG Inserting order '2' for instance 'default'
May 23 16:44:01-107933 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '2', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-108050 taler-merchant-httpd-13855 DEBUG inserting order: order_id: 2, merchant_pub: PQ436RXG.
May 23 16:44:01-121094 taler-merchant-httpd-13855 INFO Finished handling request for `/order' with status 0
May 23 16:44:01-121114 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-121157 test-merchant-api-13830 INFO looking up proposal from http://localhost:8080/public/proposal?order_id=2&instance=default&nonce=CANP5QXJJY66ZFS2EG65KZ2F59RG896BG94DS2XNDNY40M2DGRM0
May 23 16:44:01-121272 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/public/proposal'
May 23 16:44:01-121289 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-121297 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '2', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-121371 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '2', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-121529 taler-merchant-httpd-13855 DEBUG inserting contract_terms: order_id: 2, merchant_pub: PQ436RXG, h_contract_terms: 44F0RMSH.
May 23 16:44:01-138357 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-138535 test-merchant-api-13830 INFO Interpreter runs command 13/deposit-double-2(6)
May 23 16:44:01-141857 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:01-141871 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:01-151743 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-151766 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-151775 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-151789 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-151820 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-151988 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-152010 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-152024 taler-merchant-httpd-13855 DEBUG Will parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"FKKF5DTDTS7ANYDJM9GACKNECF4FC2BMAA0ZGFCXWQYE96GYD653C6SB87M1YN1VW2V3YRH6KBZR73DSV8KX2FBGZX91V90ZCC2N830"}],"order_id":"2","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:01-152031 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 1344
May 23 16:44:01-152040 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-152046 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-152051 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-152063 taler-merchant-httpd-13855 DEBUG About to parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"FKKF5DTDTS7ANYDJM9GACKNECF4FC2BMAA0ZGFCXWQYE96GYD653C6SB87M1YN1VW2V3YRH6KBZR73DSV8KX2FBGZX91V90ZCC2N830"}],"order_id":"2","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:01-152125 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '2', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-152330 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-152347 taler-merchant-httpd-13855 INFO /pay: picked instance default
May 23 16:44:01-152404 taler-merchant-httpd-13855 DEBUG Suspending /pay handling while working with the exchange
May 23 16:44:01-152414 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-152477 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms '44F0RMSH'
May 23 16:44:01-152647 taler-merchant-httpd-13855 DEBUG Looking for refund 44F0RMSH + PQ436RXG
May 23 16:44:01-152724 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-152795 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-152815 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-152828 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-152846 taler-merchant-httpd-13855 DEBUG Found transaction data for proposal `44F0RMSH' of merchant `PQ436RXG', initiating deposits
May 23 16:44:01-152886 taler-merchant-httpd-13855 DEBUG Timing for this payment, wire_deadline: 1527086641000000, refund_deadline: 0
May 23 16:44:01-160301 taler-merchant-httpd-13855 DEBUG URL for deposit: `http://localhost:8081/deposit'
May 23 16:44:01-170085 taler-exchange-httpd-13850 WARNING Deposited coin has insufficient funds left!
May 23 16:44:01-184091 taler-merchant-httpd-13855 WARNING Deposit operation failed with HTTP code 403
May 23 16:44:01-184120 taler-merchant-httpd-13855 DEBUG Aborting pending /deposit operations
May 23 16:44:01-184129 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-184262 taler-merchant-httpd-13855 DEBUG Resuming /pay handling as exchange interaction is done (403)
May 23 16:44:01-184283 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-184290 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-184296 taler-merchant-httpd-13855 DEBUG Queueing response (403) for /pay (OK).
May 23 16:44:01-184310 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-184350 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-184372 taler-merchant-httpd-13855 INFO Finished handling request for `/public/pay' with status 0
May 23 16:44:01-184392 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-184447 test-merchant-api-13830 INFO /pay completed with response code 403
May 23 16:44:01-191348 test-merchant-api-13830 INFO Accepting proof of double-spending
May 23 16:44:01-191377 test-merchant-api-13830 INFO Interpreter runs command 14/history-0(16)
May 23 16:44:01-191459 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/history'
May 23 16:44:01-191474 taler-merchant-httpd-13855 INFO Serving /history
May 23 16:44:01-191488 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-191510 taler-merchant-httpd-13855 DEBUG Querying history back to Wed May 23 17:44:01 2018, start: 10, delta: 10
May 23 16:44:01-191527 taler-merchant-httpd-13855 DEBUG DB serving /history with date Wed May 23 17:44:01 2018
May 23 16:44:01-191886 taler-merchant-httpd-13855 DEBUG /history's row_id: 1
May 23 16:44:01-191929 taler-merchant-httpd-13855 INFO /history, http code: 200
May 23 16:44:01-191969 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-192060 test-merchant-api-13830 INFO Interpreter runs command 15/create-reserve-2(2)
May 23 16:44:01-201780 test-merchant-api-13830 DEBUG Making transfer from 63 to 2 over EUR:1 and subject KG41BZTGRC8QYFAT3SWR5VWP8H84Z67EVA9KHCDATG4EA775QX8G
May 23 16:44:01-201795 test-merchant-api-13830 INFO Receiving incoming wire transfer: 63->2 from http://localhost:8081/
May 23 16:44:01-201862 test-merchant-api-13830 INFO Interpreter runs command 16/create-reserve-2b(2)
May 23 16:44:01-206959 test-merchant-api-13830 DEBUG Making transfer from 63 to 2 over EUR:4.01 and subject KG41BZTGRC8QYFAT3SWR5VWP8H84Z67EVA9KHCDATG4EA775QX8G
May 23 16:44:01-206971 test-merchant-api-13830 INFO Receiving incoming wire transfer: 63->2 from http://localhost:8081/
May 23 16:44:01-207017 test-merchant-api-13830 INFO Interpreter runs command 17/wirewatch-2(11)
May 23 16:44:01-222242 test-merchant-api-13830 INFO Client asked for up to 1024 results of type credit for account 2 starting at 1
May 23 16:44:01-222267 test-merchant-api-13830 INFO Found transaction over EUR:1 from 63 to 2
May 23 16:44:01-222281 test-merchant-api-13830 INFO Found transaction over EUR:4.01 from 63 to 2
May 23 16:44:01-230163 test-merchant-api-13830 INFO Interpreter runs command 18/check_bank_transfer-2(12)
May 23 16:44:01-230189 test-merchant-api-13830 INFO Interpreter runs command 19/check_bank_transfer-2(12)
May 23 16:44:01-230197 test-merchant-api-13830 INFO Interpreter runs command 20/withdraw-coin-2(4)
May 23 16:44:01-255296 test-merchant-api-13830 INFO Interpreter runs command 21/fetch-proposal-2(1)
May 23 16:44:01-255325 test-merchant-api-13830 INFO looking up proposal from http://localhost:8080/public/proposal?order_id=2&instance=default&nonce=CANP5QXJJY66ZFS2EG65KZ2F59RG896BG94DS2XNDNY40M2DGRM0
May 23 16:44:01-255433 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/public/proposal'
May 23 16:44:01-255452 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-255461 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '2', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-261622 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-261705 test-merchant-api-13830 INFO Interpreter runs command 22/check_bank_empty(13)
May 23 16:44:01-261723 test-merchant-api-13830 INFO Interpreter runs command 23/run-aggregator(10)
May 23 16:44:01-289201 test-merchant-api-13830 DEBUG Making transfer from 2 to 3 over EUR:4.98 and subject 6GBMWJNEWRZWWHPWFGQY3F5CX2VNRR48DC7N38TRW762EJD90HD0
May 23 16:44:01-289225 test-merchant-api-13830 INFO Receiving incoming wire transfer: 2->3 from http://localhost:8081/
May 23 16:44:01-298883 test-merchant-api-13830 INFO Interpreter runs command 24/check_bank_transfer-498c(12)
May 23 16:44:01-298908 test-merchant-api-13830 INFO Interpreter runs command 25/check_bank_empty(13)
May 23 16:44:01-298913 test-merchant-api-13830 INFO Interpreter runs command 26/track-transaction-1(15)
May 23 16:44:01-298935 test-merchant-api-13830 DEBUG Requesting URL 'http://localhost:8080/track/transaction?order_id=1&instance=default'
May 23 16:44:01-299031 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/track/transaction'
May 23 16:44:01-299059 taler-merchant-httpd-13855 DEBUG Tracking on behalf of instance 'default'
May 23 16:44:01-299068 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-299257 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms '9D95Y8QE'
May 23 16:44:01-299696 taler-merchant-httpd-13855 DEBUG Suspending /track/transaction handling while working with the exchange
May 23 16:44:01-299711 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-299715 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-299722 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-346849 taler-merchant-httpd-13855 DEBUG Resuming /track/transaction handling as exchange interaction is done (200)
May 23 16:44:01-346875 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/track/transaction'
May 23 16:44:01-346883 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /track/transaction (OK).
May 23 16:44:01-346893 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-346924 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-346938 taler-merchant-httpd-13855 INFO Finished handling request for `/track/transaction' with status 0
May 23 16:44:01-346948 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-347007 test-merchant-api-13830 INFO Interpreter runs command 27/track-transfer-1(14)
May 23 16:44:01-347143 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/track/transfer'
May 23 16:44:01-347161 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-347409 taler-merchant-httpd-13855 DEBUG Transforming /track/transfer response.
May 23 16:44:01-347699 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /track/transfer (OK).
May 23 16:44:01-347730 taler-merchant-httpd-13855 INFO Finished handling request for `/track/transfer' with status 0
May 23 16:44:01-347740 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-347805 test-merchant-api-13830 INFO Interpreter runs command 28/track-transfer-1-again(14)
May 23 16:44:01-347909 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/track/transfer'
May 23 16:44:01-347939 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-348124 taler-merchant-httpd-13855 DEBUG Transforming /track/transfer response.
May 23 16:44:01-348272 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /track/transfer (OK).
May 23 16:44:01-348302 taler-merchant-httpd-13855 INFO Finished handling request for `/track/transfer' with status 0
May 23 16:44:01-348312 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-348376 test-merchant-api-13830 INFO Interpreter runs command 29/deposit-simple-2(6)
May 23 16:44:01-350477 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:01-350485 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:01-356759 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-356774 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-356780 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-356791 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-356812 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-356940 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-356968 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-356976 taler-merchant-httpd-13855 DEBUG Will parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"YPEEKVQFAM37ASQCVE3CKQAVJ8EMMATVP19EJY3HDTAQ3CVS2QCG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26E226N334HHK70RMCD9K6RRMCC1G84WKCH1J60SKCGT66MRM4DA18CTM2H9Q8CTMCCSM8N246CJ36D34CGJ464V3CHJ46RS32H1R88W30H1G8GWMCG9J60SM4E1S70WMAH9R84TMCE1R74VKAE1R6S0M4E1R6WV34DJ18GWK4D9J6RWM6HJ460TKJC9K6X2M6HJ58CT3CCT6751K8DA36MV48CA66X0K2HA1611MAH9H852M8CJ38H2K2H23710K2H1P74VK6CT48H33AC9G8S338GJ26D138E9G6D23GH1K8S23CC9M64T3ECJ68N1K6E1G74T44HA36RV3CGSH8RR44H9S6RRK6D9R75238G9H610K2DJ5891KCDJ6850K6D2560SKAD9H6X1KAGT56S2KCCH35452081918G2J2G0","coin_sig":"94WH5ZV9G5WT6Y8Y9SESTZNT2VQZA1MFM8JW4B0VT2K00HSGQ8G3JX0JNQRAH7CBZYGY4XDV8VJ9FP0AW8T6HBJMXN01NSQMQEJQ83R"}],"order_id":"2","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:01-356987 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 1344
May 23 16:44:01-356993 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-356996 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-357000 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-357007 taler-merchant-httpd-13855 DEBUG About to parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"YPEEKVQFAM37ASQCVE3CKQAVJ8EMMATVP19EJY3HDTAQ3CVS2QCG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26E226N334HHK70RMCD9K6RRMCC1G84WKCH1J60SKCGT66MRM4DA18CTM2H9Q8CTMCCSM8N246CJ36D34CGJ464V3CHJ46RS32H1R88W30H1G8GWMCG9J60SM4E1S70WMAH9R84TMCE1R74VKAE1R6S0M4E1R6WV34DJ18GWK4D9J6RWM6HJ460TKJC9K6X2M6HJ58CT3CCT6751K8DA36MV48CA66X0K2HA1611MAH9H852M8CJ38H2K2H23710K2H1P74VK6CT48H33AC9G8S338GJ26D138E9G6D23GH1K8S23CC9M64T3ECJ68N1K6E1G74T44HA36RV3CGSH8RR44H9S6RRK6D9R75238G9H610K2DJ5891KCDJ6850K6D2560SKAD9H6X1KAGT56S2KCCH35452081918G2J2G0","coin_sig":"94WH5ZV9G5WT6Y8Y9SESTZNT2VQZA1MFM8JW4B0VT2K00HSGQ8G3JX0JNQRAH7CBZYGY4XDV8VJ9FP0AW8T6HBJMXN01NSQMQEJQ83R"}],"order_id":"2","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:01-357039 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '2', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-357188 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-357196 taler-merchant-httpd-13855 INFO /pay: picked instance default
May 23 16:44:01-357232 taler-merchant-httpd-13855 DEBUG Suspending /pay handling while working with the exchange
May 23 16:44:01-357238 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-357305 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms '44F0RMSH'
May 23 16:44:01-357391 taler-merchant-httpd-13855 DEBUG Looking for refund 44F0RMSH + PQ436RXG
May 23 16:44:01-357467 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-357539 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-357543 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-357550 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-357560 taler-merchant-httpd-13855 DEBUG Found transaction data for proposal `44F0RMSH' of merchant `PQ436RXG', initiating deposits
May 23 16:44:01-357586 taler-merchant-httpd-13855 DEBUG Timing for this payment, wire_deadline: 1527086641000000, refund_deadline: 0
May 23 16:44:01-362139 taler-merchant-httpd-13855 DEBUG URL for deposit: `http://localhost:8081/deposit'
May 23 16:44:01-381447 taler-merchant-httpd-13855 DEBUG Storing successful payment for h_contract_terms `44F0RMSH' and merchant `PQ436RXG'
May 23 16:44:01-381473 taler-merchant-httpd-13855 DEBUG Storing payment for h_contract_terms `44F0RMSH', coin_pub: `XARW4PJG', amount_with_fee: EUR:5
May 23 16:44:01-381479 taler-merchant-httpd-13855 DEBUG Merchant pub is `PQ436RXG'
May 23 16:44:01-387883 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-388042 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms '44F0RMSH'
May 23 16:44:01-388216 taler-merchant-httpd-13855 DEBUG Looking for refund 44F0RMSH + PQ436RXG
May 23 16:44:01-388397 taler-merchant-httpd-13855 INFO Subtracting total refunds from paid amount: EUR:0
May 23 16:44:01-388413 taler-merchant-httpd-13855 DEBUG Marking proposal paid, h_contract_terms: '44F0RMSH', merchant_pub: 'PQ436RXG'
May 23 16:44:01-388649 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-396193 taler-merchant-httpd-13855 DEBUG Looking for refund 44F0RMSH + PQ436RXG
May 23 16:44:01-402340 taler-merchant-httpd-13855 DEBUG Resuming /pay handling as exchange interaction is done (200)
May 23 16:44:01-402358 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-402364 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-402368 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /pay (OK).
May 23 16:44:01-402378 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-402406 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-402428 taler-merchant-httpd-13855 INFO Finished handling request for `/public/pay' with status 0
May 23 16:44:01-402446 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-402489 test-merchant-api-13830 INFO /pay completed with response code 200
May 23 16:44:01-406716 test-merchant-api-13830 INFO Interpreter runs command 30/run-aggregator-2(10)
May 23 16:44:01-439781 test-merchant-api-13830 DEBUG Making transfer from 2 to 3 over EUR:4.98 and subject 4VE32EXJNMAYBATKE92SVMW0ED3ZH6JZ6FJ82JN9HQMPP2FYQJ50
May 23 16:44:01-439803 test-merchant-api-13830 INFO Receiving incoming wire transfer: 2->3 from http://localhost:8081/
May 23 16:44:01-448553 test-merchant-api-13830 INFO Interpreter runs command 31/check_bank_transfer-498c-2(12)
May 23 16:44:01-448587 test-merchant-api-13830 INFO Interpreter runs command 32/check_bank_empty(13)
May 23 16:44:01-448596 test-merchant-api-13830 INFO Interpreter runs command 33/track-transfer-2(14)
May 23 16:44:01-448716 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/track/transfer'
May 23 16:44:01-448742 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-448902 taler-merchant-httpd-13855 DEBUG Suspending /track/transfer handling while working with the exchange
May 23 16:44:01-448917 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-448921 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-448928 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-456601 taler-merchant-httpd-13855 INFO Got response code 200 from exchange for /track/transfer
May 23 16:44:01-479749 taler-merchant-httpd-13855 DEBUG About to call tracks transformator.
May 23 16:44:01-479779 taler-merchant-httpd-13855 DEBUG Transforming /track/transfer response.
May 23 16:44:01-480053 taler-merchant-httpd-13855 DEBUG Resuming /track/transfer handling as exchange interaction is done (200)
May 23 16:44:01-480075 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/track/transfer'
May 23 16:44:01-480086 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /track/transfer (OK).
May 23 16:44:01-480102 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-480150 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-480191 taler-merchant-httpd-13855 INFO Finished handling request for `/track/transfer' with status 0
May 23 16:44:01-480213 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-480260 test-merchant-api-13830 INFO Interpreter runs command 34/track-transfer-2-again(14)
May 23 16:44:01-480433 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/track/transfer'
May 23 16:44:01-480461 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-480772 taler-merchant-httpd-13855 DEBUG Transforming /track/transfer response.
May 23 16:44:01-481155 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /track/transfer (OK).
May 23 16:44:01-481206 taler-merchant-httpd-13855 INFO Finished handling request for `/track/transfer' with status 0
May 23 16:44:01-481222 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-481306 test-merchant-api-13830 INFO Interpreter runs command 35/track-transaction-2(15)
May 23 16:44:01-481330 test-merchant-api-13830 DEBUG Requesting URL 'http://localhost:8080/track/transaction?order_id=2&instance=default'
May 23 16:44:01-481457 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/track/transaction'
May 23 16:44:01-481482 taler-merchant-httpd-13855 DEBUG Tracking on behalf of instance 'default'
May 23 16:44:01-481493 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '2', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-481803 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms '44F0RMSH'
May 23 16:44:01-482296 taler-merchant-httpd-13855 DEBUG Suspending /track/transaction handling while working with the exchange
May 23 16:44:01-482326 taler-merchant-httpd-13855 DEBUG Resuming /track/transaction handling as exchange interaction is done (200)
May 23 16:44:01-482340 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/track/transaction'
May 23 16:44:01-482348 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /track/transaction (OK).
May 23 16:44:01-482362 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-482393 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-482414 taler-merchant-httpd-13855 INFO Finished handling request for `/track/transaction' with status 0
May 23 16:44:01-482427 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-482476 test-merchant-api-13830 INFO Interpreter runs command 36/history-1(16)
May 23 16:44:01-482559 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/history'
May 23 16:44:01-482568 taler-merchant-httpd-13855 INFO Serving /history
May 23 16:44:01-482578 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-482589 taler-merchant-httpd-13855 DEBUG Querying history back to Wed May 23 17:44:01 2018, start: 10, delta: 10
May 23 16:44:01-482597 taler-merchant-httpd-13855 DEBUG DB serving /history with date Wed May 23 17:44:01 2018
May 23 16:44:01-482880 taler-merchant-httpd-13855 DEBUG /history's row_id: 2
May 23 16:44:01-482935 taler-merchant-httpd-13855 DEBUG /history's row_id: 1
May 23 16:44:01-482962 taler-merchant-httpd-13855 INFO /history, http code: 200
May 23 16:44:01-482996 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-483089 test-merchant-api-13830 INFO Interpreter runs command 37/history-2(16)
May 23 16:44:01-483167 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/history'
May 23 16:44:01-483175 taler-merchant-httpd-13855 INFO Serving /history
May 23 16:44:01-483185 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-483196 taler-merchant-httpd-13855 DEBUG Querying history back to Thu Jan 01 01:00:00 1970, start: 10, delta: 10
May 23 16:44:01-483204 taler-merchant-httpd-13855 DEBUG DB serving /history with date Thu Jan 01 01:00:00 1970
May 23 16:44:01-483431 taler-merchant-httpd-13855 INFO /history, http code: 200
May 23 16:44:01-483461 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-483523 test-merchant-api-13830 INFO Interpreter runs command 38/refund-increase-1(17)
May 23 16:44:01-483692 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/refund'
May 23 16:44:01-483717 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-483727 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/refund'
May 23 16:44:01-483734 taler-merchant-httpd-13855 DEBUG Will parse: {"refund":"EUR:0.1","order_id":"1","reason":"refund test","instance":"default"}
May 23 16:44:01-483740 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 79
May 23 16:44:01-483747 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/refund'
May 23 16:44:01-483752 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-483758 taler-merchant-httpd-13855 DEBUG About to parse: {"refund":"EUR:0.1","order_id":"1","reason":"refund test","instance":"default"}
May 23 16:44:01-483774 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-483784 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-484051 taler-merchant-httpd-13855 DEBUG Asked to refund EUR:0.1 on contract 9D95Y8QE
May 23 16:44:01-484072 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-484546 taler-merchant-httpd-13855 DEBUG Existing refund for coin ZGGH7V4V is EUR:0
May 23 16:44:01-484573 taler-merchant-httpd-13855 DEBUG Total existing refund is EUR:0
May 23 16:44:01-484587 taler-merchant-httpd-13855 DEBUG Coin ZGGH7V4V deposit amount is EUR:5
May 23 16:44:01-484597 taler-merchant-httpd-13855 DEBUG Coin ZGGH7V4V refund will be incremented by EUR:0.1
May 23 16:44:01-484612 taler-merchant-httpd-13855 DEBUG Inserting refund 9D95Y8QE + PQ436RXG
May 23 16:44:01-485071 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-496398 taler-merchant-httpd-13855 DEBUG Committed refund transaction
May 23 16:44:01-518803 taler-merchant-httpd-13855 INFO Finished handling request for `/refund' with status 0
May 23 16:44:01-518858 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-519036 test-merchant-api-13830 INFO Interpreter runs command 39/refund-lookup-1(18)
May 23 16:44:01-519284 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/public/refund'
May 23 16:44:01-519361 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-519403 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-519950 taler-merchant-httpd-13855 DEBUG Looking for refund 9D95Y8QE + PQ436RXG
May 23 16:44:01-520370 taler-merchant-httpd-13855 DEBUG Found refund of ZGGH7V4V for coin EUR:0.1 with reason `refund test' in database
May 23 16:44:01-535271 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-538515 test-merchant-api-13830 INFO Interpreter runs command 40/create-reserve-tip-1(2)
May 23 16:44:01-544024 test-merchant-api-13830 DEBUG Making transfer from 62 to 2 over EUR:20.04 and subject STV3MPMED169CF855K9M46ND60HPB4Y7VP4HS8PA7N6YQ7CJW5HG
May 23 16:44:01-544038 test-merchant-api-13830 INFO Receiving incoming wire transfer: 62->2 from http://localhost:8081/
May 23 16:44:01-544101 test-merchant-api-13830 INFO Interpreter runs command 41/wirewatch-3(11)
May 23 16:44:01-563592 test-merchant-api-13830 INFO Client asked for up to 1024 results of type credit for account 2 starting at 3
May 23 16:44:01-563638 test-merchant-api-13830 INFO Found transaction over EUR:4.98 from 2 to 3
May 23 16:44:01-563644 test-merchant-api-13830 INFO Found transaction over EUR:4.98 from 2 to 3
May 23 16:44:01-563648 test-merchant-api-13830 INFO Found transaction over EUR:20.04 from 62 to 2
May 23 16:44:01-572227 test-merchant-api-13830 INFO Interpreter runs command 42/check_bank_transfer-tip-1(12)
May 23 16:44:01-572263 test-merchant-api-13830 INFO Interpreter runs command 43/authorize-tip-1(19)
May 23 16:44:01-572299 test-merchant-api-13830 DEBUG Requesting URL 'http://localhost:8080/tip-authorize'
May 23 16:44:01-572396 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-572423 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-572441 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-572450 taler-merchant-httpd-13855 DEBUG Will parse: {"amount":"EUR:5.01","instance":"tip","justification":"tip 1","pickup_url":"http://merchant.com/pickup","next_url":"http://merchant.com/continue"}
May 23 16:44:01-572459 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 146
May 23 16:44:01-572467 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-572475 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-572482 taler-merchant-httpd-13855 DEBUG About to parse: {"amount":"EUR:5.01","instance":"tip","justification":"tip 1","pickup_url":"http://merchant.com/pickup","next_url":"http://merchant.com/continue"}
May 23 16:44:01-572506 taler-merchant-httpd-13855 DEBUG Looking for by-id key XHEG0WCG of 'tip' in hashmap
May 23 16:44:01-572517 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-572856 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-572942 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-572953 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-572965 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-577450 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-578195 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-604862 taler-merchant-httpd-13855 DEBUG Resuming HTTP processing
May 23 16:44:01-604910 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-604930 taler-merchant-httpd-13855 DEBUG Looking for by-id key XHEG0WCG of 'tip' in hashmap
May 23 16:44:01-604943 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-607043 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-613303 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-613440 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-613493 taler-merchant-httpd-13855 INFO Finished handling request for `/tip-authorize' with status 0
May 23 16:44:01-613523 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-613674 test-merchant-api-13830 INFO Interpreter runs command 44/authorize-tip-2(19)
May 23 16:44:01-613746 test-merchant-api-13830 DEBUG Requesting URL 'http://localhost:8080/tip-authorize'
May 23 16:44:01-613922 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-613971 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-613998 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-614015 taler-merchant-httpd-13855 DEBUG Will parse: {"amount":"EUR:5.01","instance":"tip","justification":"tip 2","pickup_url":"http://merchant.com/pickup","next_url":"http://merchant.com/continue"}
May 23 16:44:01-614029 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 146
May 23 16:44:01-614042 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-614055 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-614067 taler-merchant-httpd-13855 DEBUG About to parse: {"amount":"EUR:5.01","instance":"tip","justification":"tip 2","pickup_url":"http://merchant.com/pickup","next_url":"http://merchant.com/continue"}
May 23 16:44:01-614107 taler-merchant-httpd-13855 DEBUG Looking for by-id key XHEG0WCG of 'tip' in hashmap
May 23 16:44:01-614124 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-616321 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-621669 taler-merchant-httpd-13855 INFO Finished handling request for `/tip-authorize' with status 0
May 23 16:44:01-621741 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-621897 test-merchant-api-13830 INFO Interpreter runs command 45/query-tip-1(22)
May 23 16:44:01-621967 test-merchant-api-13830 INFO Requesting URL 'http://localhost:8080/tip-query?instance=tip'
May 23 16:44:01-622156 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/tip-query'
May 23 16:44:01-622217 taler-merchant-httpd-13855 DEBUG Looking for by-id key XHEG0WCG of 'tip' in hashmap
May 23 16:44:01-622750 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-622799 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-622824 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-634265 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-634858 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-642910 taler-merchant-httpd-13855 DEBUG Resuming /tip-query response (200)
May 23 16:44:01-642959 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/tip-query'
May 23 16:44:01-642985 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /tip-query (OK).
May 23 16:44:01-643019 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-643109 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-643161 taler-merchant-httpd-13855 INFO Finished handling request for `/tip-query' with status 0
May 23 16:44:01-643190 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-643266 test-merchant-api-13830 DEBUG Got /tip-query response with status code 200
May 23 16:44:01-643339 test-merchant-api-13830 INFO Tip query callback at command 45/query-tip-1(22)
May 23 16:44:01-643386 test-merchant-api-13830 INFO Interpreter runs command 46/query-tip-2(22)
May 23 16:44:01-643409 test-merchant-api-13830 INFO Requesting URL 'http://localhost:8080/tip-query?instance=tip'
May 23 16:44:01-643564 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/tip-query'
May 23 16:44:01-643595 taler-merchant-httpd-13855 DEBUG Looking for by-id key XHEG0WCG of 'tip' in hashmap
May 23 16:44:01-643990 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-644016 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-644035 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-653400 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-653853 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-659481 taler-merchant-httpd-13855 DEBUG Resuming /tip-query response (200)
May 23 16:44:01-659516 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/tip-query'
May 23 16:44:01-659529 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /tip-query (OK).
May 23 16:44:01-659551 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-659608 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-659642 taler-merchant-httpd-13855 INFO Finished handling request for `/tip-query' with status 0
May 23 16:44:01-659661 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-659715 test-merchant-api-13830 DEBUG Got /tip-query response with status code 200
May 23 16:44:01-659770 test-merchant-api-13830 INFO Tip query callback at command 46/query-tip-2(22)
May 23 16:44:01-659792 test-merchant-api-13830 INFO expected available EUR:20.04, actual EUR:20.04
May 23 16:44:01-659803 test-merchant-api-13830 INFO expected authorized EUR:10.02, actual EUR:10.02
May 23 16:44:01-659813 test-merchant-api-13830 INFO expected picked_up EUR:0, actual EUR:0
May 23 16:44:01-659832 test-merchant-api-13830 INFO Interpreter runs command 47/pickup-tip-1(20)
May 23 16:44:01-664552 test-merchant-api-13830 DEBUG Requesting URL 'http://localhost:8080/public/tip-pickup'
May 23 16:44:01-664680 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-664708 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-664724 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-664735 taler-merchant-httpd-13855 DEBUG Will parse: {"tip_id":"CAP8PCQVRXNYHDQJNZ1B36YJXA4027F02ZAKX01H90KZJ978RH32MVB8BM150X11NX8YQBC89XG5VE7BQCB29HRF95CGSF91DTW6960","planchets":[{"denom_pub_hash":"W60NNXH62WW86ZT329W75XHV8KMQK2VSKRWSP0ZVX9HZJ20W43CBWR33N82Z2VAXVEDW4R5SVM98HTYT61Q1EQM25N07K9SN23GNW10","coin_ev":"68MWWTGJ3HNH51X2VP76B4Y81R8ZPV3PBVWCXPE3M6CF7761NBBJQ1AQ1AXS2DV09PFGMCVRSQ84CEM7KDR5KMVP1YTVDEK0688VW9YK6F9RSNSKPVNHD4818NFS7X6BW4YCF3DJ74N55YV1V71R4CTKHQ1874JABVY0CR1DMT5WA08GEZX9D538PZS54X5SZ3VEHXMXZGEM0"}]}
May 23 16:44:01-664743 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 473
May 23 16:44:01-664752 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-664759 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-664768 taler-merchant-httpd-13855 DEBUG About to parse: {"tip_id":"CAP8PCQVRXNYHDQJNZ1B36YJXA4027F02ZAKX01H90KZJ978RH32MVB8BM150X11NX8YQBC89XG5VE7BQCB29HRF95CGSF91DTW6960","planchets":[{"denom_pub_hash":"W60NNXH62WW86ZT329W75XHV8KMQK2VSKRWSP0ZVX9HZJ20W43CBWR33N82Z2VAXVEDW4R5SVM98HTYT61Q1EQM25N07K9SN23GNW10","coin_ev":"68MWWTGJ3HNH51X2VP76B4Y81R8ZPV3PBVWCXPE3M6CF7761NBBJQ1AQ1AXS2DV09PFGMCVRSQ84CEM7KDR5KMVP1YTVDEK0688VW9YK6F9RSNSKPVNHD4818NFS7X6BW4YCF3DJ74N55YV1V71R4CTKHQ1874JABVY0CR1DMT5WA08GEZX9D538PZS54X5SZ3VEHXMXZGEM0"}]}
May 23 16:44:01-665131 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-665156 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-665172 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-665196 taler-merchant-httpd-13855 DEBUG Calculating tip amount over 1 planchets!
May 23 16:44:01-665239 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-665251 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-666997 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-686488 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-686544 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-686568 taler-merchant-httpd-13855 INFO Finished handling request for `/public/tip-pickup' with status 0
May 23 16:44:01-686582 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-686639 test-merchant-api-13830 DEBUG Obtained 1 signatures for withdrawal from picking up a tip
May 23 16:44:01-706175 test-merchant-api-13830 DEBUG Withdraw operation 0 completed with 200 (0)
May 23 16:44:01-706206 test-merchant-api-13830 INFO Interpreter runs command 48/query-tip-3(22)
May 23 16:44:01-706214 test-merchant-api-13830 INFO Requesting URL 'http://localhost:8080/tip-query?instance=tip'
May 23 16:44:01-706324 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/tip-query'
May 23 16:44:01-706345 taler-merchant-httpd-13855 DEBUG Looking for by-id key XHEG0WCG of 'tip' in hashmap
May 23 16:44:01-706595 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-706610 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-706617 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-714784 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-714970 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-717282 taler-merchant-httpd-13855 DEBUG Resuming /tip-query response (200)
May 23 16:44:01-717303 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/tip-query'
May 23 16:44:01-717310 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /tip-query (OK).
May 23 16:44:01-717319 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-717348 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-717363 taler-merchant-httpd-13855 INFO Finished handling request for `/tip-query' with status 0
May 23 16:44:01-717372 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-717411 test-merchant-api-13830 DEBUG Got /tip-query response with status code 200
May 23 16:44:01-717432 test-merchant-api-13830 INFO Tip query callback at command 48/query-tip-3(22)
May 23 16:44:01-717439 test-merchant-api-13830 INFO expected available EUR:15.03, actual EUR:15.03
May 23 16:44:01-717444 test-merchant-api-13830 INFO expected picked_up EUR:5.01, actual EUR:5.01
May 23 16:44:01-717455 test-merchant-api-13830 INFO Interpreter runs command 49/pickup-tip-2(20)
May 23 16:44:01-720124 test-merchant-api-13830 DEBUG Requesting URL 'http://localhost:8080/public/tip-pickup'
May 23 16:44:01-720187 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-720196 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-720203 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-720209 taler-merchant-httpd-13855 DEBUG Will parse: {"tip_id":"P1H4KQC1A8DMPFC75GEJ3XFRM9XYQ85GZ3DDCYJCS8YBBVTM97G5V9F3NKRY0M59ASAFEFC8YX6SMSA3Z9J6QSQC95JE9GY8NVZ38N0","planchets":[{"denom_pub_hash":"W60NNXH62WW86ZT329W75XHV8KMQK2VSKRWSP0ZVX9HZJ20W43CBWR33N82Z2VAXVEDW4R5SVM98HTYT61Q1EQM25N07K9SN23GNW10","coin_ev":"99F392H0FRY3N8TP5DFSFCG5ZE70P8NPA5N364MTXAA7KBHGS2Y9JHW548VV30ZQW9VY4DAGPNRC14SG5X1EPFTJA5NZ5FWTSHFFPZHTSK7G34BMF82Z41J5YHDKC484SR04N7B0E8JFZ6CQ6XRKV261EGW5WKA3CKJ6BA3P2FS0CVM2A04CMW66TYMAYMVH5W1KD7PCXV2JW"}]}
May 23 16:44:01-720214 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 473
May 23 16:44:01-720218 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-720222 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-720227 taler-merchant-httpd-13855 DEBUG About to parse: {"tip_id":"P1H4KQC1A8DMPFC75GEJ3XFRM9XYQ85GZ3DDCYJCS8YBBVTM97G5V9F3NKRY0M59ASAFEFC8YX6SMSA3Z9J6QSQC95JE9GY8NVZ38N0","planchets":[{"denom_pub_hash":"W60NNXH62WW86ZT329W75XHV8KMQK2VSKRWSP0ZVX9HZJ20W43CBWR33N82Z2VAXVEDW4R5SVM98HTYT61Q1EQM25N07K9SN23GNW10","coin_ev":"99F392H0FRY3N8TP5DFSFCG5ZE70P8NPA5N364MTXAA7KBHGS2Y9JHW548VV30ZQW9VY4DAGPNRC14SG5X1EPFTJA5NZ5FWTSHFFPZHTSK7G34BMF82Z41J5YHDKC484SR04N7B0E8JFZ6CQ6XRKV261EGW5WKA3CKJ6BA3P2FS0CVM2A04CMW66TYMAYMVH5W1KD7PCXV2JW"}]}
May 23 16:44:01-720388 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-720396 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-720403 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-720411 taler-merchant-httpd-13855 DEBUG Calculating tip amount over 1 planchets!
May 23 16:44:01-720426 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-720431 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-720936 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-738510 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-738550 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-738566 taler-merchant-httpd-13855 INFO Finished handling request for `/public/tip-pickup' with status 0
May 23 16:44:01-738576 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-738618 test-merchant-api-13830 DEBUG Obtained 1 signatures for withdrawal from picking up a tip
May 23 16:44:01-755666 test-merchant-api-13830 DEBUG Withdraw operation 0 completed with 200 (0)
May 23 16:44:01-755706 test-merchant-api-13830 INFO Interpreter runs command 50/query-tip-4(22)
May 23 16:44:01-755715 test-merchant-api-13830 INFO Requesting URL 'http://localhost:8080/tip-query?instance=tip'
May 23 16:44:01-755826 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/tip-query'
May 23 16:44:01-755846 taler-merchant-httpd-13855 DEBUG Looking for by-id key XHEG0WCG of 'tip' in hashmap
May 23 16:44:01-756112 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-756124 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-756131 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-769097 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-769323 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-771420 taler-merchant-httpd-13855 DEBUG Resuming /tip-query response (200)
May 23 16:44:01-771437 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/tip-query'
May 23 16:44:01-771442 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /tip-query (OK).
May 23 16:44:01-771451 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-771479 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-771493 taler-merchant-httpd-13855 INFO Finished handling request for `/tip-query' with status 0
May 23 16:44:01-771500 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-771516 test-merchant-api-13830 DEBUG Got /tip-query response with status code 200
May 23 16:44:01-771534 test-merchant-api-13830 INFO Tip query callback at command 50/query-tip-4(22)
May 23 16:44:01-771540 test-merchant-api-13830 INFO expected available EUR:10.02, actual EUR:10.02
May 23 16:44:01-771545 test-merchant-api-13830 INFO expected authorized EUR:10.02, actual EUR:10.02
May 23 16:44:01-771549 test-merchant-api-13830 INFO expected picked_up EUR:10.02, actual EUR:10.02
May 23 16:44:01-771558 test-merchant-api-13830 INFO Interpreter runs command 51/pickup-tip-2b(20)
May 23 16:44:01-773879 test-merchant-api-13830 DEBUG Requesting URL 'http://localhost:8080/public/tip-pickup'
May 23 16:44:01-773956 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-773971 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-773980 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-773985 taler-merchant-httpd-13855 DEBUG Will parse: {"tip_id":"P1H4KQC1A8DMPFC75GEJ3XFRM9XYQ85GZ3DDCYJCS8YBBVTM97G5V9F3NKRY0M59ASAFEFC8YX6SMSA3Z9J6QSQC95JE9GY8NVZ38N0","planchets":[{"denom_pub_hash":"W60NNXH62WW86ZT329W75XHV8KMQK2VSKRWSP0ZVX9HZJ20W43CBWR33N82Z2VAXVEDW4R5SVM98HTYT61Q1EQM25N07K9SN23GNW10","coin_ev":"99F392H0FRY3N8TP5DFSFCG5ZE70P8NPA5N364MTXAA7KBHGS2Y9JHW548VV30ZQW9VY4DAGPNRC14SG5X1EPFTJA5NZ5FWTSHFFPZHTSK7G34BMF82Z41J5YHDKC484SR04N7B0E8JFZ6CQ6XRKV261EGW5WKA3CKJ6BA3P2FS0CVM2A04CMW66TYMAYMVH5W1KD7PCXV2JW"}]}
May 23 16:44:01-773989 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 473
May 23 16:44:01-773993 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-773997 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-774001 taler-merchant-httpd-13855 DEBUG About to parse: {"tip_id":"P1H4KQC1A8DMPFC75GEJ3XFRM9XYQ85GZ3DDCYJCS8YBBVTM97G5V9F3NKRY0M59ASAFEFC8YX6SMSA3Z9J6QSQC95JE9GY8NVZ38N0","planchets":[{"denom_pub_hash":"W60NNXH62WW86ZT329W75XHV8KMQK2VSKRWSP0ZVX9HZJ20W43CBWR33N82Z2VAXVEDW4R5SVM98HTYT61Q1EQM25N07K9SN23GNW10","coin_ev":"99F392H0FRY3N8TP5DFSFCG5ZE70P8NPA5N364MTXAA7KBHGS2Y9JHW548VV30ZQW9VY4DAGPNRC14SG5X1EPFTJA5NZ5FWTSHFFPZHTSK7G34BMF82Z41J5YHDKC484SR04N7B0E8JFZ6CQ6XRKV261EGW5WKA3CKJ6BA3P2FS0CVM2A04CMW66TYMAYMVH5W1KD7PCXV2JW"}]}
May 23 16:44:01-774147 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-774166 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-774175 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-774183 taler-merchant-httpd-13855 DEBUG Calculating tip amount over 1 planchets!
May 23 16:44:01-774198 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-774203 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-774432 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-781896 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-781921 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-781935 taler-merchant-httpd-13855 INFO Finished handling request for `/public/tip-pickup' with status 0
May 23 16:44:01-781942 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-781954 test-merchant-api-13830 DEBUG Obtained 1 signatures for withdrawal from picking up a tip
May 23 16:44:01-788691 test-merchant-api-13830 DEBUG Withdraw operation 0 completed with 200 (0)
May 23 16:44:01-788712 test-merchant-api-13830 INFO Interpreter runs command 52/create-insufficient-funds-tip-reserve(2)
May 23 16:44:01-792357 test-merchant-api-13830 DEBUG Making transfer from 62 to 2 over EUR:1.01 and subject VY959V0VJS2JT57YHM748EAHVSSRKNWM40JA012NEJCHVK10C4AG
May 23 16:44:01-792366 test-merchant-api-13830 INFO Receiving incoming wire transfer: 62->2 from http://localhost:8081/
May 23 16:44:01-792410 test-merchant-api-13830 INFO Interpreter runs command 53/wirewatch-insufficient-funds-tip-reserve(11)
May 23 16:44:01-805359 test-merchant-api-13830 INFO Client asked for up to 1024 results of type credit for account 2 starting at 6
May 23 16:44:01-805383 test-merchant-api-13830 INFO Found transaction over EUR:1.01 from 62 to 2
May 23 16:44:01-838923 test-merchant-api-13830 INFO Interpreter runs command 54/check_bank_transfer-insufficient-funds-tip-reserve(12)
May 23 16:44:01-838952 test-merchant-api-13830 INFO Interpreter runs command 55/authorize-tip-3-insufficient-funds(19)
May 23 16:44:01-838972 test-merchant-api-13830 DEBUG Requesting URL 'http://localhost:8080/tip-authorize'
May 23 16:44:01-839047 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-839071 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-839087 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-839096 taler-merchant-httpd-13855 DEBUG Will parse: {"amount":"EUR:5.01","instance":"dtip","justification":"tip 3","pickup_url":"http://merchant.com/pickup","next_url":"http://merchant.com/continue"}
May 23 16:44:01-839103 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 147
May 23 16:44:01-839111 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-839117 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-839124 taler-merchant-httpd-13855 DEBUG About to parse: {"amount":"EUR:5.01","instance":"dtip","justification":"tip 3","pickup_url":"http://merchant.com/pickup","next_url":"http://merchant.com/continue"}
May 23 16:44:01-839147 taler-merchant-httpd-13855 DEBUG Looking for by-id key A0QMH4JJ of 'dtip' in hashmap
May 23 16:44:01-839157 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-839400 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-839488 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-839499 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-839510 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-843422 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-843841 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-854815 taler-merchant-httpd-13855 DEBUG Resuming HTTP processing
May 23 16:44:01-854850 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-854862 taler-merchant-httpd-13855 DEBUG Looking for by-id key A0QMH4JJ of 'dtip' in hashmap
May 23 16:44:01-854870 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-855239 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-855447 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-855504 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-855527 taler-merchant-httpd-13855 INFO Finished handling request for `/tip-authorize' with status 0
May 23 16:44:01-855540 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-855595 test-merchant-api-13830 INFO Interpreter runs command 56/authorize-tip-4-unknown-instance(19)
May 23 16:44:01-855627 test-merchant-api-13830 DEBUG Requesting URL 'http://localhost:8080/tip-authorize'
May 23 16:44:01-855718 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-855730 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-855739 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-855746 taler-merchant-httpd-13855 DEBUG Will parse: {"amount":"EUR:5.01","instance":"unknown","justification":"tip 4","pickup_url":"http://merchant.com/pickup","next_url":"http://merchant.com/continue"}
May 23 16:44:01-855751 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 150
May 23 16:44:01-855757 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-855763 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-855768 taler-merchant-httpd-13855 DEBUG About to parse: {"amount":"EUR:5.01","instance":"unknown","justification":"tip 4","pickup_url":"http://merchant.com/pickup","next_url":"http://merchant.com/continue"}
May 23 16:44:01-855785 taler-merchant-httpd-13855 DEBUG Looking for by-id key QA7GTE9Q of 'unknown' in hashmap
May 23 16:44:01-855799 taler-merchant-httpd-13855 WARNING Instance `unknown' not configured
May 23 16:44:01-855829 taler-merchant-httpd-13855 INFO Finished handling request for `/tip-authorize' with status 0
May 23 16:44:01-855841 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-855852 test-merchant-api-13830 INFO Interpreter runs command 57/authorize-tip-5-notip-instance(19)
May 23 16:44:01-855873 test-merchant-api-13830 DEBUG Requesting URL 'http://localhost:8080/tip-authorize'
May 23 16:44:01-855919 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-855926 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-855933 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-855939 taler-merchant-httpd-13855 DEBUG Will parse: {"amount":"EUR:5.01","instance":"default","justification":"tip 5","pickup_url":"http://merchant.com/pickup","next_url":"http://merchant.com/continue"}
May 23 16:44:01-855945 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 150
May 23 16:44:01-855950 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/tip-authorize'
May 23 16:44:01-855955 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-855960 taler-merchant-httpd-13855 DEBUG About to parse: {"amount":"EUR:5.01","instance":"default","justification":"tip 5","pickup_url":"http://merchant.com/pickup","next_url":"http://merchant.com/continue"}
May 23 16:44:01-855974 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-855983 taler-merchant-httpd-13855 WARNING Instance `default' not configured for tipping
May 23 16:44:01-856009 taler-merchant-httpd-13855 INFO Finished handling request for `/tip-authorize' with status 0
May 23 16:44:01-856020 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-856030 test-merchant-api-13830 INFO Interpreter runs command 58/pickup-tip-3-too-much(20)
May 23 16:44:01-859468 test-merchant-api-13830 DEBUG Requesting URL 'http://localhost:8080/public/tip-pickup'
May 23 16:44:01-859591 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-859613 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-859622 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-859630 taler-merchant-httpd-13855 DEBUG Will parse: {"tip_id":"CAP8PCQVRXNYHDQJNZ1B36YJXA4027F02ZAKX01H90KZJ978RH32MVB8BM150X11NX8YQBC89XG5VE7BQCB29HRF95CGSF91DTW6960","planchets":[{"denom_pub_hash":"W60NNXH62WW86ZT329W75XHV8KMQK2VSKRWSP0ZVX9HZJ20W43CBWR33N82Z2VAXVEDW4R5SVM98HTYT61Q1EQM25N07K9SN23GNW10","coin_ev":"GQMRM52ENQ3CA9E6HTWVA5C83EZF2Q2NH1G6B5D1TFB87W2NW0Y7RFJ24MFEN1YRA9DBAWR8FDPB8NAK7V2BB2RZM811GPEKCE7SBG478T58KQ6ZZQ1HZBXS0MDYFVXNC5N3VA3H6D7NBEV9WMJY1Q49Q923KR58555GGKEN7Z6MR0GYWSR0X0KCP2D8WKDVS7ZXGR3CDYVJG"}]}
May 23 16:44:01-859636 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 473
May 23 16:44:01-859643 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-859648 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-859655 taler-merchant-httpd-13855 DEBUG About to parse: {"tip_id":"CAP8PCQVRXNYHDQJNZ1B36YJXA4027F02ZAKX01H90KZJ978RH32MVB8BM150X11NX8YQBC89XG5VE7BQCB29HRF95CGSF91DTW6960","planchets":[{"denom_pub_hash":"W60NNXH62WW86ZT329W75XHV8KMQK2VSKRWSP0ZVX9HZJ20W43CBWR33N82Z2VAXVEDW4R5SVM98HTYT61Q1EQM25N07K9SN23GNW10","coin_ev":"GQMRM52ENQ3CA9E6HTWVA5C83EZF2Q2NH1G6B5D1TFB87W2NW0Y7RFJ24MFEN1YRA9DBAWR8FDPB8NAK7V2BB2RZM811GPEKCE7SBG478T58KQ6ZZQ1HZBXS0MDYFVXNC5N3VA3H6D7NBEV9WMJY1Q49Q923KR58555GGKEN7Z6MR0GYWSR0X0KCP2D8WKDVS7ZXGR3CDYVJG"}]}
May 23 16:44:01-859916 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-859927 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-859937 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-859949 taler-merchant-httpd-13855 DEBUG Calculating tip amount over 1 planchets!
May 23 16:44:01-859976 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/tip-pickup'
May 23 16:44:01-859984 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-860277 taler-merchant-httpd-13855 WARNING External protocol violation detected at plugin_merchantdb_postgres.c:3366.
May 23 16:44:01-860303 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-860497 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-860542 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-860565 taler-merchant-httpd-13855 INFO Finished handling request for `/public/tip-pickup' with status 0
May 23 16:44:01-860577 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-860621 test-merchant-api-13830 INFO Interpreter runs command 59/create-proposal-tip-1(5)
May 23 16:44:01-860816 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:01-860837 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-860846 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:01-860853 taler-merchant-httpd-13855 DEBUG Will parse: {"order":{"max_fee":{"currency":"EUR","value":0,"fraction":50000000},"order_id":"1-tip","refund_deadline":"/Date(0)/","pay_deadline":"/Date(99999999999)/","amount":{"currency":"EUR","value":5,"fraction":0},"summary":"merchant-lib testcase","fulfillment_url":"https://example.com/","products":[{"description":"ice cream tip","value":"{EUR:5}"}],"merchant":{"instance":"default"}}}
May 23 16:44:01-860859 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 379
May 23 16:44:01-860866 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:01-860878 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-860885 taler-merchant-httpd-13855 DEBUG About to parse: {"order":{"max_fee":{"currency":"EUR","value":0,"fraction":50000000},"order_id":"1-tip","refund_deadline":"/Date(0)/","pay_deadline":"/Date(99999999999)/","amount":{"currency":"EUR","value":5,"fraction":0},"summary":"merchant-lib testcase","fulfillment_url":"https://example.com/","products":[{"description":"ice cream tip","value":"{EUR:5}"}],"merchant":{"instance":"default"}}}
May 23 16:44:01-860920 taler-merchant-httpd-13855 DEBUG Giving 'default' instance
May 23 16:44:01-860929 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-860943 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-860954 taler-merchant-httpd-13855 DEBUG Inserting order '1-tip' for instance 'default'
May 23 16:44:01-860962 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1-tip', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-861225 taler-merchant-httpd-13855 DEBUG inserting order: order_id: 1-tip, merchant_pub: PQ436RXG.
May 23 16:44:01-871654 taler-merchant-httpd-13855 INFO Finished handling request for `/order' with status 0
May 23 16:44:01-871681 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-871733 test-merchant-api-13830 INFO looking up proposal from http://localhost:8080/public/proposal?order_id=1-tip&instance=default&nonce=WJQVP8T96NQ7FC8S49Y55JVJSKBT0DN358PH111BN47WMN4TB050
May 23 16:44:01-871839 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/public/proposal'
May 23 16:44:01-871854 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-871864 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1-tip', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-871955 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1-tip', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-872138 taler-merchant-httpd-13855 DEBUG inserting contract_terms: order_id: 1-tip, merchant_pub: PQ436RXG, h_contract_terms: MN6EWW3A.
May 23 16:44:01-892291 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-892503 test-merchant-api-13830 INFO Interpreter runs command 60/deposit-tip-simple(6)
May 23 16:44:01-896971 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:01-896989 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:01-910193 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-910224 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-910236 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-910253 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-910292 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-910439 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-910466 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-910484 taler-merchant-httpd-13855 DEBUG Will parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"PEM563SYQZGTCPSG0ZKZ11Q5HNEACPQ3ARX1HNE0B2GAQ4ZADW80","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26G9Q88TM6DSJ850M8C9K650KCH9S8CWKEC9Q6S0K6HJ460T46DJ46N2MCC9Q6MR30H246914ADA28H2M8DA288T34CHK6CT34HHS6CWMAE9S61242DJ38N33EE1K890K6C1S8RSKCE1Q6RT38CA46GVMCE1P8N2K4D21650K4DHN70R32H238CRM8GHK8H0M6DSJ6GW34DA36CS36HHS6RVKJC2484TM2C9P8S348C2374V38H246H13JG9J64S46DSS6H2K6H258N238E256S248H1S6D13JH1S8D23GGA660TKEHJ565344C1Q8GRM6CT58CWKEDHG6CTMCDHH6WVM2HHH6WTKED1N650KEGHQ610KECJ2612K2C9P8GWKAG9R8MRM6G9P6CR4CCSG64W4CDS35452081918G2J2G0","coin_sig":"4T10VT4SRE8SG7DHBHJHEDFRJEEPPT9P7K4SKQNA09NSP4ZF4KDMBXAHZTWTNP50H0AKKQPK7ARF3QG305A13YK1HYBMGGD8QB8CJ2R"}],"order_id":"1-tip","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:01-910503 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 1348
May 23 16:44:01-910515 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-910522 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-910529 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:01-910544 taler-merchant-httpd-13855 DEBUG About to parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"PEM563SYQZGTCPSG0ZKZ11Q5HNEACPQ3ARX1HNE0B2GAQ4ZADW80","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26G9Q88TM6DSJ850M8C9K650KCH9S8CWKEC9Q6S0K6HJ460T46DJ46N2MCC9Q6MR30H246914ADA28H2M8DA288T34CHK6CT34HHS6CWMAE9S61242DJ38N33EE1K890K6C1S8RSKCE1Q6RT38CA46GVMCE1P8N2K4D21650K4DHN70R32H238CRM8GHK8H0M6DSJ6GW34DA36CS36HHS6RVKJC2484TM2C9P8S348C2374V38H246H13JG9J64S46DSS6H2K6H258N238E256S248H1S6D13JH1S8D23GGA660TKEHJ565344C1Q8GRM6CT58CWKEDHG6CTMCDHH6WVM2HHH6WTKED1N650KEGHQ610KECJ2612K2C9P8GWKAG9R8MRM6G9P6CR4CCSG64W4CDS35452081918G2J2G0","coin_sig":"4T10VT4SRE8SG7DHBHJHEDFRJEEPPT9P7K4SKQNA09NSP4ZF4KDMBXAHZTWTNP50H0AKKQPK7ARF3QG305A13YK1HYBMGGD8QB8CJ2R"}],"order_id":"1-tip","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:01-910608 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '1-tip', merchant_pub: 'PQ436RXG'.
May 23 16:44:01-910957 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:01-910985 taler-merchant-httpd-13855 INFO /pay: picked instance default
May 23 16:44:01-911059 taler-merchant-httpd-13855 DEBUG Suspending /pay handling while working with the exchange
May 23 16:44:01-911074 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-911268 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms 'MN6EWW3A'
May 23 16:44:01-911528 taler-merchant-httpd-13855 DEBUG Looking for refund MN6EWW3A + PQ436RXG
May 23 16:44:01-911775 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:01-911900 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:01-911913 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:01-911931 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-911955 taler-merchant-httpd-13855 DEBUG Found transaction data for proposal `MN6EWW3A' of merchant `PQ436RXG', initiating deposits
May 23 16:44:01-912007 taler-merchant-httpd-13855 DEBUG Timing for this payment, wire_deadline: 1527086641000000, refund_deadline: 0
May 23 16:44:01-921370 taler-merchant-httpd-13855 DEBUG URL for deposit: `http://localhost:8081/deposit'
May 23 16:44:01-958535 taler-merchant-httpd-13855 DEBUG Storing successful payment for h_contract_terms `MN6EWW3A' and merchant `PQ436RXG'
May 23 16:44:01-958579 taler-merchant-httpd-13855 DEBUG Storing payment for h_contract_terms `MN6EWW3A', coin_pub: `Q5WXA1JY', amount_with_fee: EUR:5
May 23 16:44:01-958589 taler-merchant-httpd-13855 DEBUG Merchant pub is `PQ436RXG'
May 23 16:44:01-963217 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:01-963323 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms 'MN6EWW3A'
May 23 16:44:01-963480 taler-merchant-httpd-13855 DEBUG Looking for refund MN6EWW3A + PQ436RXG
May 23 16:44:01-963543 taler-merchant-httpd-13855 INFO Subtracting total refunds from paid amount: EUR:0
May 23 16:44:01-963555 taler-merchant-httpd-13855 DEBUG Marking proposal paid, h_contract_terms: 'MN6EWW3A', merchant_pub: 'PQ436RXG'
May 23 16:44:01-963749 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:01-988062 taler-merchant-httpd-13855 DEBUG Looking for refund MN6EWW3A + PQ436RXG
May 23 16:44:01-995714 taler-merchant-httpd-13855 DEBUG Resuming /pay handling as exchange interaction is done (200)
May 23 16:44:01-995738 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:01-995745 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:01-995750 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /pay (OK).
May 23 16:44:01-995764 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-995806 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-995834 taler-merchant-httpd-13855 INFO Finished handling request for `/public/pay' with status 0
May 23 16:44:01-995856 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:01-995907 test-merchant-api-13830 INFO /pay completed with response code 200
May 23 16:44:02-001644 test-merchant-api-13830 INFO Interpreter runs command 61/run-aggregator-tip-1(10)
May 23 16:44:02-048411 test-merchant-api-13830 DEBUG Making transfer from 2 to 3 over EUR:4.98 and subject ZGTWZ4M5117JCAAS5TSPFYEKK4995MZ4BCHEMGFCCFW0R45M00Z0
May 23 16:44:02-048433 test-merchant-api-13830 INFO Receiving incoming wire transfer: 2->3 from http://localhost:8081/
May 23 16:44:02-058147 test-merchant-api-13830 INFO Interpreter runs command 62/check_bank_transfer-tip-498c(12)
May 23 16:44:02-058176 test-merchant-api-13830 INFO Interpreter runs command 63/check_bank_empty(13)
May 23 16:44:02-058182 test-merchant-api-13830 INFO Interpreter runs command 64/create-reserve-10(2)
May 23 16:44:02-065673 test-merchant-api-13830 DEBUG Making transfer from 63 to 2 over EUR:10.02 and subject YE2H3E4CE4F3PHQXK1S6BMNDQNEJEGVZWE7V6CRW17TV06Y5HN6G
May 23 16:44:02-065687 test-merchant-api-13830 INFO Receiving incoming wire transfer: 63->2 from http://localhost:8081/
May 23 16:44:02-065752 test-merchant-api-13830 INFO Interpreter runs command 65/wirewatch-10(11)
May 23 16:44:02-083018 test-merchant-api-13830 INFO Client asked for up to 1024 results of type credit for account 2 starting at 7
May 23 16:44:02-083046 test-merchant-api-13830 INFO Found transaction over EUR:4.98 from 2 to 3
May 23 16:44:02-083051 test-merchant-api-13830 INFO Found transaction over EUR:10.02 from 63 to 2
May 23 16:44:02-089055 test-merchant-api-13830 INFO Interpreter runs command 66/check_bank_transfer-10(12)
May 23 16:44:02-089092 test-merchant-api-13830 INFO Interpreter runs command 67/withdraw-coin-10a(4)
May 23 16:44:02-114217 test-merchant-api-13830 INFO Interpreter runs command 68/withdraw-coin-10b(4)
May 23 16:44:02-141169 test-merchant-api-13830 INFO Interpreter runs command 69/withdraw-status-10(3)
May 23 16:44:02-170361 test-merchant-api-13830 INFO Interpreter runs command 70/create-proposal-10(5)
May 23 16:44:02-170559 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:02-170580 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-170595 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:02-170602 taler-merchant-httpd-13855 DEBUG Will parse: {"order":{"max_fee":{"currency":"EUR","value":0,"fraction":50000000},"order_id":"10","refund_deadline":"/Date(0)/","pay_deadline":"/Date(99999999999)/","amount":{"currency":"EUR","value":10,"fraction":0},"summary":"merchant-lib testcase","fulfillment_url":"https://example.com/","products":[{"description":"ice cream","value":"{EUR:10}"}],"merchant":{"instance":"default"}}}
May 23 16:44:02-170615 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 374
May 23 16:44:02-170621 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:02-170626 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-170631 taler-merchant-httpd-13855 DEBUG About to parse: {"order":{"max_fee":{"currency":"EUR","value":0,"fraction":50000000},"order_id":"10","refund_deadline":"/Date(0)/","pay_deadline":"/Date(99999999999)/","amount":{"currency":"EUR","value":10,"fraction":0},"summary":"merchant-lib testcase","fulfillment_url":"https://example.com/","products":[{"description":"ice cream","value":"{EUR:10}"}],"merchant":{"instance":"default"}}}
May 23 16:44:02-170661 taler-merchant-httpd-13855 DEBUG Giving 'default' instance
May 23 16:44:02-170669 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:02-170682 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:02-170691 taler-merchant-httpd-13855 DEBUG Inserting order '10' for instance 'default'
May 23 16:44:02-170698 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '10', merchant_pub: 'PQ436RXG'.
May 23 16:44:02-170905 taler-merchant-httpd-13855 DEBUG inserting order: order_id: 10, merchant_pub: PQ436RXG.
May 23 16:44:02-180030 taler-merchant-httpd-13855 INFO Finished handling request for `/order' with status 0
May 23 16:44:02-180050 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-180105 test-merchant-api-13830 INFO looking up proposal from http://localhost:8080/public/proposal?order_id=10&instance=default&nonce=YESGR7R7Y9MWHZHQFXHE7VY19GSR9RPG1H09XV1MB58MZZ86SJBG
May 23 16:44:02-180170 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/public/proposal'
May 23 16:44:02-180182 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:02-180189 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '10', merchant_pub: 'PQ436RXG'.
May 23 16:44:02-180390 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '10', merchant_pub: 'PQ436RXG'.
May 23 16:44:02-180635 taler-merchant-httpd-13855 DEBUG inserting contract_terms: order_id: 10, merchant_pub: PQ436RXG, h_contract_terms: ED7XFBWA.
May 23 16:44:02-195054 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-195185 test-merchant-api-13830 INFO Interpreter runs command 71/pay-fail-partial-double-10(6)
May 23 16:44:02-197439 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:02-197449 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:02-206213 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:02-206221 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:02-212948 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-212964 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-212970 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-212980 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-213001 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-213135 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-213163 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-213177 taler-merchant-httpd-13855 DEBUG Will parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"PF8FZ6AMSP25KDBKH366HQFEQM4HYESKHD9PH7J84D1AHB0GY760","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26D228S332E9R6X134CHJ8N0KEHHM84W4ADJ288TM4G9J8S348EA28D0KJCA56RT30G9M8GT3EGHP8MT44GJ670VKGE9S88VKCH1J6H2KEH9K88SKGC9P6S33AG9K68RK2CT36933EDJ174TK2GA568SK4CT264RKACT388RM2DA28513EHJ364VM2GJ68S33CGA160W44GSG8RTKJH9G6H1K6DA165232E9K64S4CH1M610K6H1N6WSKGD1Q64V3AH1N8D1KGDSK610K4DA364W3GGJ274R3EHJ56133GCSK6RW3AGA388RK6CSM74VKEGT26RWM8GT58N232CSS6CV38DA66S1M2HHS89144GJ684RM2DA48MTKGH9N8MV3CHA26RR4AD2388S3CCHQ6D332HH35452081918G2J2G0","coin_sig":"8A5JDKFC6NX3D57QXF0FJE84HN72H74VE9GSRNMP2EQNS045VE8X9YCW2WZAXFQWA2HDB7FMNTDDZVXN49Q127GE32XXWSK46TTTA3R"},{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"HPZBV77NRNTF53GB7J1BAPVJY368Y0A30TN0E518M6P0Z7DT1A241X4ZGQASWZGKC0ZMVJMMJVEQDDVC4GBTDW0ADHTYFHDYB77BY30"}],"order_id":"10","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:02-213187 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 2580
May 23 16:44:02-213194 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-213197 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-213201 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-213213 taler-merchant-httpd-13855 DEBUG About to parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"PF8FZ6AMSP25KDBKH366HQFEQM4HYESKHD9PH7J84D1AHB0GY760","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26D228S332E9R6X134CHJ8N0KEHHM84W4ADJ288TM4G9J8S348EA28D0KJCA56RT30G9M8GT3EGHP8MT44GJ670VKGE9S88VKCH1J6H2KEH9K88SKGC9P6S33AG9K68RK2CT36933EDJ174TK2GA568SK4CT264RKACT388RM2DA28513EHJ364VM2GJ68S33CGA160W44GSG8RTKJH9G6H1K6DA165232E9K64S4CH1M610K6H1N6WSKGD1Q64V3AH1N8D1KGDSK610K4DA364W3GGJ274R3EHJ56133GCSK6RW3AGA388RK6CSM74VKEGT26RWM8GT58N232CSS6CV38DA66S1M2HHS89144GJ684RM2DA48MTKGH9N8MV3CHA26RR4AD2388S3CCHQ6D332HH35452081918G2J2G0","coin_sig":"8A5JDKFC6NX3D57QXF0FJE84HN72H74VE9GSRNMP2EQNS045VE8X9YCW2WZAXFQWA2HDB7FMNTDDZVXN49Q127GE32XXWSK46TTTA3R"},{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"HPZBV77NRNTF53GB7J1BAPVJY368Y0A30TN0E518M6P0Z7DT1A241X4ZGQASWZGKC0ZMVJMMJVEQDDVC4GBTDW0ADHTYFHDYB77BY30"}],"order_id":"10","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:02-213271 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '10', merchant_pub: 'PQ436RXG'.
May 23 16:44:02-213517 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:02-213532 taler-merchant-httpd-13855 INFO /pay: picked instance default
May 23 16:44:02-213592 taler-merchant-httpd-13855 DEBUG Suspending /pay handling while working with the exchange
May 23 16:44:02-213599 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:02-213744 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms 'ED7XFBWA'
May 23 16:44:02-213950 taler-merchant-httpd-13855 DEBUG Looking for refund ED7XFBWA + PQ436RXG
May 23 16:44:02-214122 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:02-214291 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:02-214319 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:02-214329 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-214342 taler-merchant-httpd-13855 DEBUG Found transaction data for proposal `ED7XFBWA' of merchant `PQ436RXG', initiating deposits
May 23 16:44:02-214370 taler-merchant-httpd-13855 DEBUG Timing for this payment, wire_deadline: 1527086642000000, refund_deadline: 0
May 23 16:44:02-219437 taler-merchant-httpd-13855 DEBUG URL for deposit: `http://localhost:8081/deposit'
May 23 16:44:02-219473 taler-merchant-httpd-13855 DEBUG Timing for this payment, wire_deadline: 1527086642000000, refund_deadline: 0
May 23 16:44:02-224542 taler-merchant-httpd-13855 DEBUG URL for deposit: `http://localhost:8081/deposit'
May 23 16:44:02-251185 taler-exchange-httpd-13850 WARNING Deposited coin has insufficient funds left!
May 23 16:44:02-260224 taler-merchant-httpd-13855 DEBUG Storing successful payment for h_contract_terms `ED7XFBWA' and merchant `PQ436RXG'
May 23 16:44:02-260247 taler-merchant-httpd-13855 DEBUG Storing payment for h_contract_terms `ED7XFBWA', coin_pub: `GDW7XW90', amount_with_fee: EUR:5
May 23 16:44:02-260253 taler-merchant-httpd-13855 DEBUG Merchant pub is `PQ436RXG'
May 23 16:44:02-267559 taler-merchant-httpd-13855 WARNING Deposit operation failed with HTTP code 403
May 23 16:44:02-267575 taler-merchant-httpd-13855 DEBUG Aborting pending /deposit operations
May 23 16:44:02-267580 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:02-267759 taler-merchant-httpd-13855 DEBUG Resuming /pay handling as exchange interaction is done (403)
May 23 16:44:02-267776 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-267781 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-267785 taler-merchant-httpd-13855 DEBUG Queueing response (403) for /pay (OK).
May 23 16:44:02-267794 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-267822 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-267837 taler-merchant-httpd-13855 INFO Finished handling request for `/public/pay' with status 0
May 23 16:44:02-267855 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-267906 test-merchant-api-13830 INFO /pay completed with response code 403
May 23 16:44:02-272004 test-merchant-api-13830 INFO Accepting proof of double-spending
May 23 16:44:02-272025 test-merchant-api-13830 INFO Interpreter runs command 72/pay-again-10(7)
May 23 16:44:02-273984 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:02-273992 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:02-281657 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:02-281665 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:02-287261 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-287287 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-287292 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-287301 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-287317 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-287431 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-287457 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-287468 taler-merchant-httpd-13855 DEBUG Will parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"PF8FZ6AMSP25KDBKH366HQFEQM4HYESKHD9PH7J84D1AHB0GY760","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26D228S332E9R6X134CHJ8N0KEHHM84W4ADJ288TM4G9J8S348EA28D0KJCA56RT30G9M8GT3EGHP8MT44GJ670VKGE9S88VKCH1J6H2KEH9K88SKGC9P6S33AG9K68RK2CT36933EDJ174TK2GA568SK4CT264RKACT388RM2DA28513EHJ364VM2GJ68S33CGA160W44GSG8RTKJH9G6H1K6DA165232E9K64S4CH1M610K6H1N6WSKGD1Q64V3AH1N8D1KGDSK610K4DA364W3GGJ274R3EHJ56133GCSK6RW3AGA388RK6CSM74VKEGT26RWM8GT58N232CSS6CV38DA66S1M2HHS89144GJ684RM2DA48MTKGH9N8MV3CHA26RR4AD2388S3CCHQ6D332HH35452081918G2J2G0","coin_sig":"8A5JDKFC6NX3D57QXF0FJE84HN72H74VE9GSRNMP2EQNS045VE8X9YCW2WZAXFQWA2HDB7FMNTDDZVXN49Q127GE32XXWSK46TTTA3R"},{"contribution":"EUR:5","coin_pub":"DGG0SSR5GJSC21EAME38G07XRCYX9FNQPC2XFKMV991K2NHEYMTG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26CJ1850KJGA26RRMCDSR6RWMAEA66CW38H9P74V34D1J68RKJCHJ6MVK8GT5612M4DT66CRM8DHS64T32DHN6MS46DSN8MWM6CSG8S1M6HHM88RKEE2568T42DA68MWK2GSJ8H33JC9N8CW32H9J8D0KGG9G6GW30DHN8923EDA2751M6HA18GV4AGSP892K2E1Q8N23JC1R8S13AC9K6N0M6D2670R3ADHS60WM8GSM6GT30GSR88SM2E236CTKEHA375148D1H6D0M2GT460T3GDT6691K8H2674TM6HHH8H2MAC9R6RR32C9S6513GDA48CS36C9P64WK4HHH68VK4DA46MSK4CSQ8GWKAH2661144C1G8D344D246X1K2E1H8CW46CHQ6934CEA26CV30GH35452081918G2J2G0","coin_sig":"E3D1H9YERXV7ZZRDKX8NKZ2V1WBKFBGMJP96GC3XN4JJ5Z94DGY2J38X0SDR6H5A0NQQ9DC966AYV2FAFW07T78HEM10A1QNYXD340G"}],"order_id":"10","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:02-287472 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 2580
May 23 16:44:02-287480 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-287483 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-287486 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-287496 taler-merchant-httpd-13855 DEBUG About to parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"PF8FZ6AMSP25KDBKH366HQFEQM4HYESKHD9PH7J84D1AHB0GY760","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26D228S332E9R6X134CHJ8N0KEHHM84W4ADJ288TM4G9J8S348EA28D0KJCA56RT30G9M8GT3EGHP8MT44GJ670VKGE9S88VKCH1J6H2KEH9K88SKGC9P6S33AG9K68RK2CT36933EDJ174TK2GA568SK4CT264RKACT388RM2DA28513EHJ364VM2GJ68S33CGA160W44GSG8RTKJH9G6H1K6DA165232E9K64S4CH1M610K6H1N6WSKGD1Q64V3AH1N8D1KGDSK610K4DA364W3GGJ274R3EHJ56133GCSK6RW3AGA388RK6CSM74VKEGT26RWM8GT58N232CSS6CV38DA66S1M2HHS89144GJ684RM2DA48MTKGH9N8MV3CHA26RR4AD2388S3CCHQ6D332HH35452081918G2J2G0","coin_sig":"8A5JDKFC6NX3D57QXF0FJE84HN72H74VE9GSRNMP2EQNS045VE8X9YCW2WZAXFQWA2HDB7FMNTDDZVXN49Q127GE32XXWSK46TTTA3R"},{"contribution":"EUR:5","coin_pub":"DGG0SSR5GJSC21EAME38G07XRCYX9FNQPC2XFKMV991K2NHEYMTG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26CJ1850KJGA26RRMCDSR6RWMAEA66CW38H9P74V34D1J68RKJCHJ6MVK8GT5612M4DT66CRM8DHS64T32DHN6MS46DSN8MWM6CSG8S1M6HHM88RKEE2568T42DA68MWK2GSJ8H33JC9N8CW32H9J8D0KGG9G6GW30DHN8923EDA2751M6HA18GV4AGSP892K2E1Q8N23JC1R8S13AC9K6N0M6D2670R3ADHS60WM8GSM6GT30GSR88SM2E236CTKEHA375148D1H6D0M2GT460T3GDT6691K8H2674TM6HHH8H2MAC9R6RR32C9S6513GDA48CS36C9P64WK4HHH68VK4DA46MSK4CSQ8GWKAH2661144C1G8D344D246X1K2E1H8CW46CHQ6934CEA26CV30GH35452081918G2J2G0","coin_sig":"E3D1H9YERXV7ZZRDKX8NKZ2V1WBKFBGMJP96GC3XN4JJ5Z94DGY2J38X0SDR6H5A0NQQ9DC966AYV2FAFW07T78HEM10A1QNYXD340G"}],"order_id":"10","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:02-287539 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '10', merchant_pub: 'PQ436RXG'.
May 23 16:44:02-287759 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:02-287770 taler-merchant-httpd-13855 INFO /pay: picked instance default
May 23 16:44:02-287817 taler-merchant-httpd-13855 DEBUG Suspending /pay handling while working with the exchange
May 23 16:44:02-287823 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:02-287947 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms 'ED7XFBWA'
May 23 16:44:02-288144 taler-merchant-httpd-13855 DEBUG Coin (GDW7XW90) already found in our DB.
May 23 16:44:02-288164 taler-merchant-httpd-13855 DEBUG Looking for refund ED7XFBWA + PQ436RXG
May 23 16:44:02-288313 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:02-288476 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:02-288502 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:02-288510 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-288524 taler-merchant-httpd-13855 DEBUG Found transaction data for proposal `ED7XFBWA' of merchant `PQ436RXG', initiating deposits
May 23 16:44:02-288546 taler-merchant-httpd-13855 DEBUG Timing for this payment, wire_deadline: 1527086642000000, refund_deadline: 0
May 23 16:44:02-292282 taler-merchant-httpd-13855 DEBUG URL for deposit: `http://localhost:8081/deposit'
May 23 16:44:02-313577 taler-merchant-httpd-13855 DEBUG Storing successful payment for h_contract_terms `ED7XFBWA' and merchant `PQ436RXG'
May 23 16:44:02-313593 taler-merchant-httpd-13855 DEBUG Storing payment for h_contract_terms `ED7XFBWA', coin_pub: `41VSGZ09', amount_with_fee: EUR:5
May 23 16:44:02-313598 taler-merchant-httpd-13855 DEBUG Merchant pub is `PQ436RXG'
May 23 16:44:02-322224 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:02-322369 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms 'ED7XFBWA'
May 23 16:44:02-322586 taler-merchant-httpd-13855 DEBUG Looking for refund ED7XFBWA + PQ436RXG
May 23 16:44:02-322742 taler-merchant-httpd-13855 INFO Subtracting total refunds from paid amount: EUR:0
May 23 16:44:02-322769 taler-merchant-httpd-13855 DEBUG Marking proposal paid, h_contract_terms: 'ED7XFBWA', merchant_pub: 'PQ436RXG'
May 23 16:44:02-322978 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:02-330114 taler-merchant-httpd-13855 DEBUG Looking for refund ED7XFBWA + PQ436RXG
May 23 16:44:02-335597 taler-merchant-httpd-13855 DEBUG Resuming /pay handling as exchange interaction is done (200)
May 23 16:44:02-335612 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-335617 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-335620 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /pay (OK).
May 23 16:44:02-335629 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-335655 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-335675 taler-merchant-httpd-13855 INFO Finished handling request for `/public/pay' with status 0
May 23 16:44:02-335692 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-335730 test-merchant-api-13830 INFO /pay completed with response code 200
May 23 16:44:02-339688 test-merchant-api-13830 INFO Interpreter runs command 73/run-aggregator-10(10)
May 23 16:44:02-365099 test-merchant-api-13830 DEBUG Making transfer from 2 to 3 over EUR:9.97 and subject MWS9DYZBG04TWN25G9FZ0VHNHSJC46NJMCEJ630PT4W0FZT7VYW0
May 23 16:44:02-365169 test-merchant-api-13830 INFO Receiving incoming wire transfer: 2->3 from http://localhost:8081/
May 23 16:44:02-377531 test-merchant-api-13830 INFO Interpreter runs command 74/check_bank_transfer-9.97-10(12)
May 23 16:44:02-377605 test-merchant-api-13830 INFO Interpreter runs command 75/check_bank_empty-10(13)
May 23 16:44:02-377626 test-merchant-api-13830 INFO Interpreter runs command 76/create-reserve-11(2)
May 23 16:44:02-401594 test-merchant-api-13830 DEBUG Making transfer from 63 to 2 over EUR:10.02 and subject BDK2SHX6G877Q5Z7ETHCJ4CDZC9N4S7SY0SHSZMX8WYM5DDHHSM0
May 23 16:44:02-401631 test-merchant-api-13830 INFO Receiving incoming wire transfer: 63->2 from http://localhost:8081/
May 23 16:44:02-401766 test-merchant-api-13830 INFO Interpreter runs command 77/wirewatch-11(11)
May 23 16:44:02-424601 test-merchant-api-13830 INFO Client asked for up to 1024 results of type credit for account 2 starting at 9
May 23 16:44:02-424629 test-merchant-api-13830 INFO Found transaction over EUR:9.97 from 2 to 3
May 23 16:44:02-424635 test-merchant-api-13830 INFO Found transaction over EUR:10.02 from 63 to 2
May 23 16:44:02-456448 test-merchant-api-13830 INFO Interpreter runs command 78/check_bank_transfer-11(12)
May 23 16:44:02-456478 test-merchant-api-13830 INFO Interpreter runs command 79/withdraw-coin-11a(4)
May 23 16:44:02-483239 test-merchant-api-13830 INFO Interpreter runs command 80/withdraw-coin-11b(4)
May 23 16:44:02-522473 test-merchant-api-13830 INFO Interpreter runs command 81/withdraw-status-11(3)
May 23 16:44:02-532564 test-merchant-api-13830 INFO Interpreter runs command 82/create-proposal-11(5)
May 23 16:44:02-532685 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:02-532701 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-532712 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:02-532717 taler-merchant-httpd-13855 DEBUG Will parse: {"order":{"max_fee":{"currency":"EUR","value":0,"fraction":50000000},"order_id":"11","refund_deadline":"/Date(0)/","pay_deadline":"/Date(99999999999)/","amount":{"currency":"EUR","value":10,"fraction":0},"summary":"merchant-lib testcase","fulfillment_url":"https://example.com/","products":[{"description":"ice cream","value":"{EUR:10}"}],"merchant":{"instance":"default"}}}
May 23 16:44:02-532721 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 374
May 23 16:44:02-532724 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/order'
May 23 16:44:02-532727 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-532731 taler-merchant-httpd-13855 DEBUG About to parse: {"order":{"max_fee":{"currency":"EUR","value":0,"fraction":50000000},"order_id":"11","refund_deadline":"/Date(0)/","pay_deadline":"/Date(99999999999)/","amount":{"currency":"EUR","value":10,"fraction":0},"summary":"merchant-lib testcase","fulfillment_url":"https://example.com/","products":[{"description":"ice cream","value":"{EUR:10}"}],"merchant":{"instance":"default"}}}
May 23 16:44:02-532751 taler-merchant-httpd-13855 DEBUG Giving 'default' instance
May 23 16:44:02-532756 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:02-532764 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:02-532770 taler-merchant-httpd-13855 DEBUG Inserting order '11' for instance 'default'
May 23 16:44:02-532775 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '11', merchant_pub: 'PQ436RXG'.
May 23 16:44:02-532866 taler-merchant-httpd-13855 DEBUG inserting order: order_id: 11, merchant_pub: PQ436RXG.
May 23 16:44:02-538564 taler-merchant-httpd-13855 INFO Finished handling request for `/order' with status 0
May 23 16:44:02-538579 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-538593 test-merchant-api-13830 INFO looking up proposal from http://localhost:8080/public/proposal?order_id=11&instance=default&nonce=EABQTMNGX8VHSJE90MM7TW33AX5Q48KKD6Q5FRTK3G3M2KXFBEHG
May 23 16:44:02-538678 taler-merchant-httpd-13855 INFO Handling request (GET) for URL `/public/proposal'
May 23 16:44:02-538706 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:02-538712 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '11', merchant_pub: 'PQ436RXG'.
May 23 16:44:02-538880 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '11', merchant_pub: 'PQ436RXG'.
May 23 16:44:02-539090 taler-merchant-httpd-13855 DEBUG inserting contract_terms: order_id: 11, merchant_pub: PQ436RXG, h_contract_terms: G7M375N7.
May 23 16:44:02-551992 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-552093 test-merchant-api-13830 INFO Interpreter runs command 83/pay-fail-partial-double-11(6)
May 23 16:44:02-553801 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:02-553808 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:02-560440 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:02-560446 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:02-565550 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-565576 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-565580 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-565588 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-565609 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-565728 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-565754 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-565765 taler-merchant-httpd-13855 DEBUG Will parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"02CFAQH78RG0S18NR0M9B6TEAZRYSJH3QQS36PC6AXWERCCQ6PT0","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26G9P6MRK4DT36H1MCEA56MRM2D25692K0CA18MS46DSM84SK0GT5612KAC9N8N234C2464V36CHG8RTM4DJ66CT48E1S8RW36DA570S4CCA48MV36EA488TM2GJ588SM6E1R88RM4E1M8D2KED236RR3GCSM74S38C9M6GR32DSK8RVKCE218H34CHJ365232DJ36MT42D1J88V3AGSG8GWM4DJ4692KGG9M88W3CC236GV3AHJ66N33GGHK8RWK0GT68MR46GT5651K4DT58D230GHP6N248H1P6CS46HJ68S0KEGSQ8513EGSM612M2D1K8D342DSN60V3ACT68GTKGG9P8RW44D9J88R30DA28GW34D9S8CV42D9J6S0KAE2468T3JE1G6GRKGH9P8H2KAH935452081918G2J2G0","coin_sig":"VPXBXA6DSY1TRN6Z1W7WMFRAQG57D5SPZ2T6PQVRGT606J8Z71BX4JB9Z9ZD6PWMFB2E2MQXYRMRDZJY70KX07V0HQ6S2AKDYQWNE2R"},{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"X0BJB7VS2XW35Z6T9CGQKD13RGB2P2EFJ49BMT89KNCDPM3H06XCBC2GQSBK4SA6DV6Q3ZXGYNCJTXPY0WQCDYP7XV9S742Y6XJ3M0R"}],"order_id":"11","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:02-565768 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 2580
May 23 16:44:02-565774 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-565776 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-565779 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-565788 taler-merchant-httpd-13855 DEBUG About to parse: {"mode":"pay","coins":[{"contribution":"EUR:5","coin_pub":"02CFAQH78RG0S18NR0M9B6TEAZRYSJH3QQS36PC6AXWERCCQ6PT0","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26G9P6MRK4DT36H1MCEA56MRM2D25692K0CA18MS46DSM84SK0GT5612KAC9N8N234C2464V36CHG8RTM4DJ66CT48E1S8RW36DA570S4CCA48MV36EA488TM2GJ588SM6E1R88RM4E1M8D2KED236RR3GCSM74S38C9M6GR32DSK8RVKCE218H34CHJ365232DJ36MT42D1J88V3AGSG8GWM4DJ4692KGG9M88W3CC236GV3AHJ66N33GGHK8RWK0GT68MR46GT5651K4DT58D230GHP6N248H1P6CS46HJ68S0KEGSQ8513EGSM612M2D1K8D342DSN60V3ACT68GTKGG9P8RW44D9J88R30DA28GW34D9S8CV42D9J6S0KAE2468T3JE1G6GRKGH9P8H2KAH935452081918G2J2G0","coin_sig":"VPXBXA6DSY1TRN6Z1W7WMFRAQG57D5SPZ2T6PQVRGT606J8Z71BX4JB9Z9ZD6PWMFB2E2MQXYRMRDZJY70KX07V0HQ6S2AKDYQWNE2R"},{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"X0BJB7VS2XW35Z6T9CGQKD13RGB2P2EFJ49BMT89KNCDPM3H06XCBC2GQSBK4SA6DV6Q3ZXGYNCJTXPY0WQCDYP7XV9S742Y6XJ3M0R"}],"order_id":"11","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:02-565833 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '11', merchant_pub: 'PQ436RXG'.
May 23 16:44:02-566045 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:02-566056 taler-merchant-httpd-13855 INFO /pay: picked instance default
May 23 16:44:02-566102 taler-merchant-httpd-13855 DEBUG Suspending /pay handling while working with the exchange
May 23 16:44:02-566108 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:02-566246 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms 'G7M375N7'
May 23 16:44:02-566420 taler-merchant-httpd-13855 DEBUG Looking for refund G7M375N7 + PQ436RXG
May 23 16:44:02-566585 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:02-566731 taler-merchant-httpd-13855 DEBUG Trying to find chosen exchange `http://localhost:8081/'
May 23 16:44:02-566758 taler-merchant-httpd-13855 DEBUG The exchange `http://localhost:8081/' is already known
May 23 16:44:02-566766 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-566776 taler-merchant-httpd-13855 DEBUG Found transaction data for proposal `G7M375N7' of merchant `PQ436RXG', initiating deposits
May 23 16:44:02-566797 taler-merchant-httpd-13855 DEBUG Timing for this payment, wire_deadline: 1527086642000000, refund_deadline: 0
May 23 16:44:02-570720 taler-merchant-httpd-13855 DEBUG URL for deposit: `http://localhost:8081/deposit'
May 23 16:44:02-570747 taler-merchant-httpd-13855 DEBUG Timing for this payment, wire_deadline: 1527086642000000, refund_deadline: 0
May 23 16:44:02-574618 taler-merchant-httpd-13855 DEBUG URL for deposit: `http://localhost:8081/deposit'
May 23 16:44:02-597765 taler-exchange-httpd-13850 WARNING Deposited coin has insufficient funds left!
May 23 16:44:02-604917 taler-merchant-httpd-13855 WARNING Deposit operation failed with HTTP code 403
May 23 16:44:02-604930 taler-merchant-httpd-13855 DEBUG Aborting pending /deposit operations
May 23 16:44:02-604956 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:02-605018 taler-merchant-httpd-13855 DEBUG Resuming /pay handling as exchange interaction is done (403)
May 23 16:44:02-605026 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-605035 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-605039 taler-merchant-httpd-13855 DEBUG Queueing response (403) for /pay (OK).
May 23 16:44:02-605046 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-605067 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-605078 taler-merchant-httpd-13855 INFO Finished handling request for `/public/pay' with status 0
May 23 16:44:02-605098 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-605123 test-merchant-api-13830 INFO /pay completed with response code 403
May 23 16:44:02-608668 test-merchant-api-13830 INFO Accepting proof of double-spending
May 23 16:44:02-608687 test-merchant-api-13830 INFO Interpreter runs command 84/pay-abort-11(8)
May 23 16:44:02-610377 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:02-610383 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:02-617012 test-merchant-api-13830 DEBUG ... amount_with_fee was EUR:5
May 23 16:44:02-617019 test-merchant-api-13830 DEBUG ... fee was EUR:0.01
May 23 16:44:02-622114 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-622127 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-622132 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-622141 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-622157 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-622176 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-622181 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-622191 taler-merchant-httpd-13855 DEBUG Will parse: {"mode":"abort-refund","coins":[{"contribution":"EUR:5","coin_pub":"02CFAQH78RG0S18NR0M9B6TEAZRYSJH3QQS36PC6AXWERCCQ6PT0","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26G9P6MRK4DT36H1MCEA56MRM2D25692K0CA18MS46DSM84SK0GT5612KAC9N8N234C2464V36CHG8RTM4DJ66CT48E1S8RW36DA570S4CCA48MV36EA488TM2GJ588SM6E1R88RM4E1M8D2KED236RR3GCSM74S38C9M6GR32DSK8RVKCE218H34CHJ365232DJ36MT42D1J88V3AGSG8GWM4DJ4692KGG9M88W3CC236GV3AHJ66N33GGHK8RWK0GT68MR46GT5651K4DT58D230GHP6N248H1P6CS46HJ68S0KEGSQ8513EGSM612M2D1K8D342DSN60V3ACT68GTKGG9P8RW44D9J88R30DA28GW34D9S8CV42D9J6S0KAE2468T3JE1G6GRKGH9P8H2KAH935452081918G2J2G0","coin_sig":"VPXBXA6DSY1TRN6Z1W7WMFRAQG57D5SPZ2T6PQVRGT606J8Z71BX4JB9Z9ZD6PWMFB2E2MQXYRMRDZJY70KX07V0HQ6S2AKDYQWNE2R"},{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"X0BJB7VS2XW35Z6T9CGQKD13RGB2P2EFJ49BMT89KNCDPM3H06XCBC2GQSBK4SA6DV6Q3ZXGYNCJTXPY0WQCDYP7XV9S742Y6XJ3M0R"}],"order_id":"11","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:02-622199 taler-merchant-httpd-13855 INFO Parser asking for more data, current data size is 2589
May 23 16:44:02-622203 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-622206 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-622209 taler-merchant-httpd-13855 DEBUG Will parse: 
May 23 16:44:02-622218 taler-merchant-httpd-13855 DEBUG About to parse: {"mode":"abort-refund","coins":[{"contribution":"EUR:5","coin_pub":"02CFAQH78RG0S18NR0M9B6TEAZRYSJH3QQS36PC6AXWERCCQ6PT0","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26G9P6MRK4DT36H1MCEA56MRM2D25692K0CA18MS46DSM84SK0GT5612KAC9N8N234C2464V36CHG8RTM4DJ66CT48E1S8RW36DA570S4CCA48MV36EA488TM2GJ588SM6E1R88RM4E1M8D2KED236RR3GCSM74S38C9M6GR32DSK8RVKCE218H34CHJ365232DJ36MT42D1J88V3AGSG8GWM4DJ4692KGG9M88W3CC236GV3AHJ66N33GGHK8RWK0GT68MR46GT5651K4DT58D230GHP6N248H1P6CS46HJ68S0KEGSQ8513EGSM612M2D1K8D342DSN60V3ACT68GTKGG9P8RW44D9J88R30DA28GW34D9S8CV42D9J6S0KAE2468T3JE1G6GRKGH9P8H2KAH935452081918G2J2G0","coin_sig":"VPXBXA6DSY1TRN6Z1W7WMFRAQG57D5SPZ2T6PQVRGT606J8Z71BX4JB9Z9ZD6PWMFB2E2MQXYRMRDZJY70KX07V0HQ6S2AKDYQWNE2R"},{"contribution":"EUR:5","coin_pub":"3NQEPTV8D1X3ANGCC0EW4GFBYTHP7WVB0NWPF4Z4KW60P2EQ2TPG","exchange_url":"http://localhost:8081/","denom_pub":"51R7ARKCD5HJTTV5F4G0M818E9SP280A40G2GVH04CR30GSH610M8GSP891K8H1R85134GJ66X1KGDHJ8H332GA66MW46H1N8D2M2G9J6WRK6CJ4891M4C9J712K2DA36MV3CE1K8GSM8DHK8S13GE1H70T36DJ18GRKEGA26N34CD9G88RKAD1Q892K6D9S6H1MCGHM6513GGJ58N236CHP6GT32GJ58514CH1G8MW4CGHS6MW3JC9S6CW32H216S348GT36X0K6GSP6H2K8H9M64V3EEA26H1KCC1S70WM4C226X13AH9K6GT3EE226X334DA58MS38D1H6RWMAGSG68S36H1M612M4HJ28RTMCE1J6GRM4GA38H334E9K8H142GSS70TM8E1Q6S2K6HA38N242CSP89342H9R6N248CA56RW30E9K74WMCC1Q6133JH1354520818CMG26C1H60R30C935452081918G2J2G0","ub_sig":"51SPJSSDESGPR80A40M74WV140520818ECG26GSG8S13EC1J8GS30DSG8GV3GC1N6CRMCC9P6GR3AHA46X0M2CJ5691K2CHM88WKGH9Q6RTM6HA57124ACJ570R4CC9G8CTKCH9M74VM4H1K8D244D1P70V38CJ565248D236GSKAH1J6CW3GC9S8N2M4CT2610K2CHG6GTM4GT384TM8G9K6WVM2D1S60W3ADA474R38CHH8CWKJD9Q6RV4CH9Q710KGDHK8GTKEC1G8533JCJ560R34GHM6RW44D9Q6WV3CGHN6X33GGA569144GJ28N1K4DSS74VKACSS84SMACHQ692M8HJ36H246C9N6934AHHJ6WR36HJ484W3GG9H6H1M6C9M68WK2HJ66X1M2EA26D2K6CA36X24CDSS8MRKGDSG69130GT6611KJH935452081918G2J2G0","coin_sig":"X0BJB7VS2XW35Z6T9CGQKD13RGB2P2EFJ49BMT89KNCDPM3H06XCBC2GQSBK4SA6DV6Q3ZXGYNCJTXPY0WQCDYP7XV9S742Y6XJ3M0R"}],"order_id":"11","merchant_pub":"36V2ZCJ0WGHNH9S57WW765C594DCKYAT03F99HXWJBEAVF95FDJ0"}
May 23 16:44:02-622260 taler-merchant-httpd-13855 DEBUG Finding contract term, order_id: '11', merchant_pub: 'PQ436RXG'.
May 23 16:44:02-622477 taler-merchant-httpd-13855 DEBUG Looking for by-id key 2RJWVDTX of 'default' in hashmap
May 23 16:44:02-622488 taler-merchant-httpd-13855 INFO /pay: picked instance default
May 23 16:44:02-622534 taler-merchant-httpd-13855 DEBUG Suspending /pay handling while working with the exchange
May 23 16:44:02-622540 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:02-622677 taler-merchant-httpd-13855 DEBUG Finding payment for h_contract_terms 'G7M375N7'
May 23 16:44:02-622853 taler-merchant-httpd-13855 DEBUG Looking for refund G7M375N7 + PQ436RXG
May 23 16:44:02-623117 taler-merchant-httpd-13855 DEBUG Asked to refund EUR:0 on contract G7M375N7
May 23 16:44:02-623128 taler-merchant-httpd-13855 DEBUG Starting merchant DB transaction
May 23 16:44:02-623260 taler-merchant-httpd-13855 DEBUG Total existing refund is EUR:0
May 23 16:44:02-623279 taler-merchant-httpd-13855 ERROR Unknown contract: G7M375N7 (merchant_pub: PQ436RXG), no refund possible
May 23 16:44:02-623284 taler-merchant-httpd-13855 DEBUG Rolling back merchant DB transaction
May 23 16:44:02-623311 taler-merchant-httpd-13855 DEBUG Committing merchant DB transaction
May 23 16:44:02-623345 taler-merchant-httpd-13855 DEBUG Resuming /pay handling as exchange interaction is done (200)
May 23 16:44:02-623355 taler-merchant-httpd-13855 INFO Handling request (POST) for URL `/public/pay'
May 23 16:44:02-623358 taler-merchant-httpd-13855 DEBUG In handler for /pay.
May 23 16:44:02-623362 taler-merchant-httpd-13855 DEBUG Queueing response (200) for /pay (OK).
May 23 16:44:02-623369 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-623386 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-623397 taler-merchant-httpd-13855 INFO Finished handling request for `/public/pay' with status 0
May 23 16:44:02-623408 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
May 23 16:44:02-623420 test-merchant-api-13830 INFO /pay completed with response code 200
May 23 16:44:02-623439 test-merchant-api-13830 DEBUG Received 0 refunds
May 23 16:44:02-623457 test-merchant-api-13830 INFO Interpreter runs command 85/pay-abort-refund-11(9)
May 23 16:44:02-623468 test-merchant-api-13830 ERROR Assertion failed at test_merchant_api.c:3694.
May 23 16:44:02-623819 taler-merchant-httpd-13855 DEBUG Adding run_daemon select task
FAIL test_merchant_api (exit status: 134)
test_merchant_api.log (157,518 bytes)   

Marcello Stanisci

2018-05-23 16:53

viewer   ~0012955

Attached a log file.

Marcello Stanisci

2018-05-24 15:58

viewer   ~0012956

Commit 041ad71 is very likely a fix for this issue.
Since this is not 100% verified yet, we keep this issue
in the 'feedback' state for "a while".

Marcello Stanisci

2018-05-24 18:58

viewer  

test_merchant_api_twisted.log (9,841 bytes)   
Waiting for `taler-merchant-httpd' to be ready
.

Could connect to twister via IPC socket.
No valid hacks specified!
Could connect to twister via IPC socket.
No valid hacks specified!
Waiting for `taler-exchange-httpd' to be ready
.
May 24 18:53:05-722773 taler-exchange-httpd-11048 INFO Ensuring that tables and indices are created!
May 24 18:53:05-728697 taler-exchange-httpd-11048 INFO (re-)loading keys
May 24 18:53:05-728727 taler-exchange-httpd-11048 INFO Loading keys from `/home/marko/prog/taler/merchant/src/lib/test_merchant_api_home//.local/share/taler//exchange/live-keys/'
May 24 18:53:05-743143 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_5-5JB5S1XBPG62JD2PTYWT' (VSKH6ERV) to active set
May 24 18:53:05-751442 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_5-5JB5S1XBPG62JD2PTYWT' (SK6BA183) to active set
May 24 18:53:05-759783 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_5-5JB5S1XBPG62JD2PTYWT' (131QC8PF) to active set
May 24 18:53:05-768081 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_5-5JB5S1XBPG62JD2PTYWT' (AKE0ZWNZ) to active set
May 24 18:53:05-776433 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_5-5JB5S1XBPG62JD2PTYWT' (ECZC2GKZ) to active set
May 24 18:53:05-784737 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_0_01-G06NP4M2EJCVJAZ1P5BM' (59KM17S2) to active set
May 24 18:53:05-793086 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_0_01-G06NP4M2EJCVJAZ1P5BM' (9GQ463TP) to active set
May 24 18:53:05-801424 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_0_01-G06NP4M2EJCVJAZ1P5BM' (AGC9YJK0) to active set
May 24 18:53:05-810680 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_0_01-G06NP4M2EJCVJAZ1P5BM' (QH9Q6VKC) to active set
May 24 18:53:05-818166 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_0_01-G06NP4M2EJCVJAZ1P5BM' (TJW6S5AG) to active set
May 24 18:53:05-826430 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_0_1-V0HADRAEFKQ3N2YN2720' (DJ6E6TFT) to active set
May 24 18:53:05-834795 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_0_1-V0HADRAEFKQ3N2YN2720' (3X108NYF) to active set
May 24 18:53:05-843157 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_0_1-V0HADRAEFKQ3N2YN2720' (51EXHS4Z) to active set
May 24 18:53:05-851470 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_0_1-V0HADRAEFKQ3N2YN2720' (B9VH37PB) to active set
May 24 18:53:05-859820 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_0_1-V0HADRAEFKQ3N2YN2720' (8RYGGW7Q) to active set
May 24 18:53:05-868236 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_1-9EJZYC2VQ92ZY19Z3F71' (FS9XK91X) to active set
May 24 18:53:05-876526 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_1-9EJZYC2VQ92ZY19Z3F71' (23JAY1ZM) to active set
May 24 18:53:05-884861 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_1-9EJZYC2VQ92ZY19Z3F71' (J9ZKPK2D) to active set
May 24 18:53:05-893247 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_1-9EJZYC2VQ92ZY19Z3F71' (0XB6FRYX) to active set
May 24 18:53:05-901516 taler-exchange-httpd-11048 INFO Adding denomination key `EUR_1-9EJZYC2VQ92ZY19Z3F71' (6J7EHEYZ) to active set
May 24 18:53:06-714442 taler-exchange-httpd-11048 INFO Handling request for URL '/keys'
May 24 18:53:06-721104 test-merchant-api-twisted-11011 DEBUG Requesting keys with URL `http://localhost:8888/keys'.
May 24 18:53:06-723133 taler-exchange-httpd-11048 INFO Handling request for URL '/keys'
May 24 18:53:06-728623 test-merchant-api-twisted-11011 DEBUG Received keys from URL `http://localhost:8888/keys' with status 200.
May 24 18:53:06-916896 test-merchant-api-twisted-11011 INFO Got 20 DK from /keys
May 24 18:53:06-916952 test-merchant-api-twisted-11011 INFO Starting Fakebank on port 8082 (localhost:8082)
May 24 18:53:06-917024 test-merchant-api-twisted-11011 DEBUG Running command `proposal-for-check-payment'
May 24 18:53:06-935865 test-merchant-api-twisted-11011 INFO looking up proposal from http://localhost:8889/public/proposal?order_id=fail-check-payment-1&instance=default&nonce=TX4Q7DTDVN0Z2JFNVVXQWXTQBH95WBBK9Z2FKYRMBTZ4X02RZGKG
May 24 18:53:06-952555 test-merchant-api-twisted-11011 DEBUG Running command `non-200-response-code'
May 24 18:53:06-954621 test-merchant-api-twisted-11011 DEBUG Got SIGCHLD for `non-200-response-code'.
May 24 18:53:06-954647 test-merchant-api-twisted-11011 DEBUG Got the dead child process handle, waiting for termination ...
May 24 18:53:06-954657 test-merchant-api-twisted-11011 DEBUG ... definitively terminated
May 24 18:53:06-954660 test-merchant-api-twisted-11011 DEBUG Dead child, go on with next command.
May 24 18:53:06-954668 test-merchant-api-twisted-11011 DEBUG Running command `check-payment-fail'
May 24 18:53:06-954686 test-merchant-api-twisted-11011 DEBUG Checking for order id `fail-check-payment-1'
May 24 18:53:06-954706 test-merchant-api-twisted-11011 INFO checking payment from http://localhost:8889/check-payment?instance=default&order_id=fail-check-payment-1
May 24 18:53:06-955330 test-merchant-api-twisted-11011 WARNING Checking payment failed with HTTP status code 300
May 24 18:53:06-955344 test-merchant-api-twisted-11011 WARNING External protocol violation detected at merchant_api_check_payment.c:99.
May 24 18:53:06-955351 test-merchant-api-twisted-11011 INFO check payment: expected paid: check-payment-fail: -1
May 24 18:53:06-955354 test-merchant-api-twisted-11011 INFO check payment: paid: -1
May 24 18:53:06-955356 test-merchant-api-twisted-11011 INFO check payment: url: (null)
May 24 18:53:06-955364 test-merchant-api-twisted-11011 DEBUG Running command `hack-check-payment-0'
May 24 18:53:06-957525 test-merchant-api-twisted-11011 DEBUG Got SIGCHLD for `hack-check-payment-0'.
May 24 18:53:06-957545 test-merchant-api-twisted-11011 DEBUG Got the dead child process handle, waiting for termination ...
May 24 18:53:06-957554 test-merchant-api-twisted-11011 DEBUG ... definitively terminated
May 24 18:53:06-957557 test-merchant-api-twisted-11011 DEBUG Dead child, go on with next command.
May 24 18:53:06-957562 test-merchant-api-twisted-11011 DEBUG Running command `check-payment-fail-invalid'
May 24 18:53:06-957567 test-merchant-api-twisted-11011 DEBUG Checking for order id `fail-check-payment-1'
May 24 18:53:06-957588 test-merchant-api-twisted-11011 INFO checking payment from http://localhost:8889/check-payment?instance=default&order_id=fail-check-payment-1
May 24 18:53:06-958187 test-merchant-api-twisted-11011 WARNING no payment_redirect_url in unpaid check-payment response
May 24 18:53:06-958201 test-merchant-api-twisted-11011 WARNING External protocol violation detected at merchant_api_check_payment.c:118.
May 24 18:53:06-958205 test-merchant-api-twisted-11011 INFO check payment: expected paid: check-payment-fail-invalid: -1
May 24 18:53:06-958207 test-merchant-api-twisted-11011 INFO check payment: paid: -1
May 24 18:53:06-958210 test-merchant-api-twisted-11011 INFO check payment: url: (null)
May 24 18:53:06-958217 test-merchant-api-twisted-11011 DEBUG Running command `paid-true-for-unpaid'
May 24 18:53:06-960399 test-merchant-api-twisted-11011 DEBUG Got SIGCHLD for `paid-true-for-unpaid'.
May 24 18:53:06-960421 test-merchant-api-twisted-11011 DEBUG Got the dead child process handle, waiting for termination ...
May 24 18:53:06-960431 test-merchant-api-twisted-11011 DEBUG ... definitively terminated
May 24 18:53:06-960434 test-merchant-api-twisted-11011 DEBUG Dead child, go on with next command.
May 24 18:53:06-960439 test-merchant-api-twisted-11011 DEBUG Running command `check-payment-fail-invalid-0'
May 24 18:53:06-960444 test-merchant-api-twisted-11011 DEBUG Checking for order id `fail-check-payment-1'
May 24 18:53:06-960462 test-merchant-api-twisted-11011 INFO checking payment from http://localhost:8889/check-payment?instance=default&order_id=fail-check-payment-1
May 24 18:53:06-961206 test-merchant-api-twisted-11011 WARNING check payment failed to parse JSON
May 24 18:53:06-961220 test-merchant-api-twisted-11011 WARNING External protocol violation detected at merchant_api_check_payment.c:146.
May 24 18:53:06-961231 test-merchant-api-twisted-11011 INFO check payment: expected paid: check-payment-fail-invalid-0: -1
May 24 18:53:06-961235 test-merchant-api-twisted-11011 INFO check payment: paid: -1
May 24 18:53:06-961239 test-merchant-api-twisted-11011 INFO check payment: url: (null)
May 24 18:53:06-961250 test-merchant-api-twisted-11011 DEBUG Running command `malform-order'
May 24 18:53:06-963328 test-merchant-api-twisted-11011 DEBUG Got SIGCHLD for `malform-order'.
May 24 18:53:06-963350 test-merchant-api-twisted-11011 DEBUG Got the dead child process handle, waiting for termination ...
May 24 18:53:06-963359 test-merchant-api-twisted-11011 DEBUG ... definitively terminated
May 24 18:53:06-963362 test-merchant-api-twisted-11011 DEBUG Dead child, go on with next command.
May 24 18:53:06-963367 test-merchant-api-twisted-11011 DEBUG Running command `create-proposal-0'
May 24 18:53:06-963583 taler-merchant-httpd-11040 WARNING Failed to parse JSON request body
May 24 18:53:06-963590 twister-11046 ERROR Assertion failed at taler-twister-service.c:596.
May 24 18:53:06-963633 twister-11046 ERROR Download curl failed: Operation was aborted by an application callback
May 24 18:53:23-014677 test-merchant-api-twisted-11011 WARNING Did NOT detect response as JSON
May 24 18:53:23-014705 test-merchant-api-twisted-11011 ERROR Assertion failed at testing_api_cmd_proposal.c:287.
May 24 18:53:23-014711 test-merchant-api-twisted-11011 ERROR Failed at command `create-proposal-0'
May 24 18:53:23-014724 test-merchant-api-twisted-11011 INFO Executing shutdown at `create-proposal-0'
FAIL test_merchant_api_twisted (exit status: 1)
test_merchant_api_twisted.log (9,841 bytes)   

Marcello Stanisci

2018-05-24 18:59

viewer   ~0012957

New failure from the twisted test, possibly
due to it being too slow; whole log file attached.

Marcello Stanisci

2018-05-25 10:56

viewer   ~0012959

Resolving this and moving the twister issues in a dedicated file.

Issue History

Date Modified Username Field Change
2018-05-23 09:46 Marcello Stanisci New Issue
2018-05-23 09:46 Marcello Stanisci Status new => assigned
2018-05-23 09:46 Marcello Stanisci Assigned To => Marcello Stanisci
2018-05-23 10:13 Marcello Stanisci Note Added: 0012952
2018-05-23 10:49 Marcello Stanisci Note Added: 0012953
2018-05-23 16:53 Marcello Stanisci File Added: test_merchant_api.log
2018-05-23 16:53 Marcello Stanisci Note Added: 0012955
2018-05-24 15:58 Marcello Stanisci Status assigned => feedback
2018-05-24 15:58 Marcello Stanisci Note Added: 0012956
2018-05-24 18:58 Marcello Stanisci File Added: test_merchant_api_twisted.log
2018-05-24 18:59 Marcello Stanisci Status feedback => assigned
2018-05-24 18:59 Marcello Stanisci Note Added: 0012957
2018-05-25 10:56 Marcello Stanisci Note Added: 0012959
2018-05-25 10:56 Marcello Stanisci Status assigned => resolved
2018-05-25 10:56 Marcello Stanisci Resolution open => fixed
2018-06-12 08:59 Christian Grothoff Product Version => git (master)
2018-06-12 08:59 Christian Grothoff Fixed in Version => 0.6
2019-12-20 19:12 Christian Grothoff Status resolved => closed