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)