View Issue Details

IDProjectCategoryView StatusLast Update
0005566Talerexchangepublic2020-03-31 16:04
ReporterChristian Grothoff Assigned ToChristian Grothoff  
PrioritynormalSeveritymajorReproducibilityrandom
Status closedResolutionfixed 
Platformi7OSDebian GNU/LinuxOS Versionsqueeze
Product Versiongit (master) 
Target Version0.7.0Fixed in Version0.7.0 
Summary0005566: test_exchange_api_twisted fails
DescriptionERROR Unexpected response code 200/0 to command refresh-reveal-409-conflict in testing_api_cmd_refresh.c:324. So basically it expects a failure, but the code is happy. I suspect (did not check!) the test asks twister for a bitflip and expects a failure, but the bitflip either doesn't happen or happens in a 'harmless' place. In that case, probably specifying more precisely where to flip the bit might help.
Steps To ReproduceWas from 'make check'
Additional InformationRelevant output:

Feb 14 13:55:19-919614 util-scheduler-37494 DEBUG Running task 0x55cd166d3f20
Feb 14 13:55:19-919666 test-exchange-api-new-twisted-37494 DEBUG Downloaded body: {"ev_sigs":[{"ev_sig":"BLAH"},{"ev_sig":"BLAH"},{"ev_sig":"BLAH"},{"ev_sig":"BLAH"}]}
Feb 14 13:55:19-931249 test-exchange-api-new-twisted-37494 ERROR Unexpected response code 200/0 to command refresh-reveal-409-conflict in testing_api_cmd_refresh.c:324
{"ev_sigs": [{"ev_sig": "BLAH"}, {"ev_sig": "BLAH"}, {"ev_sig": "BLAH"}, {"ev_sig": "BLAH"}]}Feb 14 13:55:19-931331 test-exchange-api-new-twisted-37494 ERROR Failed at command `refresh-reveal-409-conflict'
Feb 14 13:55:19-931337 test-exchange-api-new-twisted-37494 ERROR Batch is at command `refresh-(flipped-)reveal'
TagsNo tags attached.
Attached Files

Activities

Christian Grothoff

2019-02-14 14:02

manager   ~0013761

I've checked, the test _sometimes_ passes and _sometimes_ fails (random), about 50/50 for me so far.

Marcello Stanisci

2019-02-14 17:05

reporter   ~0013777

I've run 5 times this test and it passes always. Please try to update the Twister, if you didn't yet.

Christian Grothoff

2019-02-14 21:28

manager   ~0013785

I did 'make install' on the latest twister, now it still fails. I got a failure like the above, and a new one:

Feb 14 21:26:44-582198 test-exchange-api-new-twisted-36970 DEBUG Downloaded body:
Feb 14 21:26:44-582235 test-exchange-api-new-twisted-36970 WARNING External protocol violation detected at json.c:71.
Feb 14 21:26:44-582247 test-exchange-api-new-twisted-36970 ERROR Unexpected response code 0 to command refund in testing_api_cmd_refund.c:112
Feb 14 21:26:44-582270 test-exchange-api-new-twisted-36970 ERROR Failed at command `refund'
Feb 14 21:26:44-582280 test-exchange-api-new-twisted-36970 ERROR Batch is at command `refund-bad-sig'

Marcello Stanisci

2019-02-15 17:04

reporter   ~0013795

I got the first error by running the test under Valgrind, but like once out of 20 runs.

Marcello Stanisci

2019-03-18 17:13

reporter   ~0014217

Attaching logs from a failing session, again not easily reproducible.
test_exchange_api_twisted.log (29,085 bytes)   
Mar 18 16:57:49-981509 taler-exchange-keyup-28914 INFO Existing keys are way too old, starting with fresh key set.
Mar 18 16:57:49-981583 taler-exchange-keyup-28914 DEBUG Generating signing key for Mon Mar 18 16:57:49 2019.
Mar 18 16:57:49-999295 taler-exchange-keyup-28914 INFO No existing keys found, starting with fresh key set.
Mar 18 16:57:49-999369 taler-exchange-keyup-28914 INFO Generating denomination key for type `coin_eur_10', start Mon Mar 18 16:57:49 2019 at /home/marcello/prog/taler/exchange/src/lib/test_exchange_api_home//.local/share/taler//exchange/live-keys//denomkeys/EUR_10-AB50VDF0GAFB6ZZSDNNN/1552924669000000
Mar 18 16:57:50-088522 taler-exchange-keyup-28914 INFO No existing keys found, starting with fresh key set.
Mar 18 16:57:50-088585 taler-exchange-keyup-28914 INFO Generating denomination key for type `coin_eur_5', start Mon Mar 18 16:57:49 2019 at /home/marcello/prog/taler/exchange/src/lib/test_exchange_api_home//.local/share/taler//exchange/live-keys//denomkeys/EUR_5-5JB5S1XBPG62JD2PTYWT/1552924669000000
Mar 18 16:57:50-128181 taler-exchange-keyup-28914 INFO No existing keys found, starting with fresh key set.
Mar 18 16:57:50-128241 taler-exchange-keyup-28914 INFO Generating denomination key for type `coin_eur_1', start Mon Mar 18 16:57:49 2019 at /home/marcello/prog/taler/exchange/src/lib/test_exchange_api_home//.local/share/taler//exchange/live-keys//denomkeys/EUR_1-9EJZYC2VQ92ZY19Z3F71/1552924669000000
Mar 18 16:57:50-178799 taler-exchange-keyup-28914 INFO No existing keys found, starting with fresh key set.
Mar 18 16:57:50-178850 taler-exchange-keyup-28914 INFO Generating denomination key for type `coin_eur_ct_10', start Mon Mar 18 16:57:49 2019 at /home/marcello/prog/taler/exchange/src/lib/test_exchange_api_home//.local/share/taler//exchange/live-keys//denomkeys/EUR_0_1-V0HADRAEFKQ3N2YN2720/1552924669000000
Mar 18 16:57:50-236699 taler-exchange-keyup-28914 INFO No existing keys found, starting with fresh key set.
Mar 18 16:57:50-236748 taler-exchange-keyup-28914 INFO Generating denomination key for type `coin_eur_ct_1', start Mon Mar 18 16:57:49 2019 at /home/marcello/prog/taler/exchange/src/lib/test_exchange_api_home//.local/share/taler//exchange/live-keys//denomkeys/EUR_0_01-G06NP4M2EJCVJAZ1P5BM/1552924669000000
Mar 18 16:57:50-262955 taler-exchange-keyup-28914 INFO Setting up wire fees for `x-taler-bank'
Mar 18 16:57:50-302646 taler-exchange-dbinit-28915 INFO Dropping ALL tables
Mar 18 16:57:50-609416 taler-auditordb-postgres-28918 INFO Dropping ALL tables
Mar 18 16:57:50-741547 test-exchange-api-new-twisted-28900 DEBUG Add exchange (http://localhost:8888/,98NJW3CQHZQGQXTY3K85K531XKPAPAVV4Q5V8PYYRR00NJGZWNVG) to the auditor
Could connect to twister via IPC socket.
No valid hacks specified!
Waiting for `taler-exchange-httpd' to be ready (check with: wget -q -t 1 -T 1 http://localhost:8888/keys -o /dev/null -O /dev/null)
.
Mar 18 16:57:50-855163 taler-exchange-httpd-28929 INFO Ensuring that tables and indices are created!
Mar 18 16:57:50-861981 taler-exchange-httpd-28929 INFO (re-)loading keys
Mar 18 16:57:50-862009 taler-exchange-httpd-28929 INFO Loading keys from `/home/marcello/prog/taler/exchange/src/lib/test_exchange_api_home//.local/share/taler//exchange/live-keys/'
Mar 18 16:57:50-862101 taler-exchange-httpd-28929 DEBUG Loading denomination key `EUR_5-5JB5S1XBPG62JD2PTYWT' (Z2A5ZVB9)
Mar 18 16:57:50-870997 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb7b17ef0
Mar 18 16:57:50-873020 taler-exchange-httpd-28929 INFO Adding denomination key `EUR_5-5JB5S1XBPG62JD2PTYWT' (Z2A5ZVB9) to active set
Mar 18 16:57:50-873115 taler-exchange-httpd-28929 DEBUG Loading denomination key `EUR_0_1-V0HADRAEFKQ3N2YN2720' (1XPSEJEX)
Mar 18 16:57:50-873132 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb7b17ef0
Mar 18 16:57:50-874724 taler-exchange-httpd-28929 INFO Adding denomination key `EUR_0_1-V0HADRAEFKQ3N2YN2720' (1XPSEJEX) to active set
Mar 18 16:57:50-874791 taler-exchange-httpd-28929 DEBUG Loading denomination key `EUR_10-AB50VDF0GAFB6ZZSDNNN' (J0Y0FRW1)
Mar 18 16:57:50-874803 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb7b17ef0
Mar 18 16:57:50-876214 taler-exchange-httpd-28929 INFO Adding denomination key `EUR_10-AB50VDF0GAFB6ZZSDNNN' (J0Y0FRW1) to active set
Mar 18 16:57:50-876265 taler-exchange-httpd-28929 DEBUG Loading denomination key `EUR_1-9EJZYC2VQ92ZY19Z3F71' (QFB83MR6)
Mar 18 16:57:50-876274 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb7b17ef0
Mar 18 16:57:50-877690 taler-exchange-httpd-28929 INFO Adding denomination key `EUR_1-9EJZYC2VQ92ZY19Z3F71' (QFB83MR6) to active set
Mar 18 16:57:50-877759 taler-exchange-httpd-28929 DEBUG Loading denomination key `EUR_0_01-G06NP4M2EJCVJAZ1P5BM' (EANAC3Z2)
Mar 18 16:57:50-877771 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb7b17ef0
Mar 18 16:57:50-879201 taler-exchange-httpd-28929 INFO Adding denomination key `EUR_0_01-G06NP4M2EJCVJAZ1P5BM' (EANAC3Z2) to active set
Mar 18 16:57:50-887177 taler-exchange-httpd-28929 DEBUG Denomination key `89QRMK3H' was revoked!
Mar 18 16:57:50-887192 taler-exchange-httpd-28929 WARNING Revoked denomination `89QRMK3H' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-894680 taler-exchange-httpd-28929 DEBUG Denomination key `20FFT71E' was revoked!
Mar 18 16:57:50-894690 taler-exchange-httpd-28929 WARNING Revoked denomination `20FFT71E' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-902123 taler-exchange-httpd-28929 DEBUG Denomination key `S4MP5248' was revoked!
Mar 18 16:57:50-902133 taler-exchange-httpd-28929 WARNING Revoked denomination `S4MP5248' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-909903 taler-exchange-httpd-28929 DEBUG Denomination key `FMYN7QC6' was revoked!
Mar 18 16:57:50-909913 taler-exchange-httpd-28929 WARNING Revoked denomination `FMYN7QC6' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-917603 taler-exchange-httpd-28929 DEBUG Denomination key `BJMHV6CX' was revoked!
Mar 18 16:57:50-917612 taler-exchange-httpd-28929 WARNING Revoked denomination `BJMHV6CX' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-925296 taler-exchange-httpd-28929 DEBUG Denomination key `7PSKAEH1' was revoked!
Mar 18 16:57:50-925305 taler-exchange-httpd-28929 WARNING Revoked denomination `7PSKAEH1' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-933231 taler-exchange-httpd-28929 DEBUG Denomination key `7W57VTVC' was revoked!
Mar 18 16:57:50-933240 taler-exchange-httpd-28929 WARNING Revoked denomination `7W57VTVC' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-941039 taler-exchange-httpd-28929 DEBUG Denomination key `A7PNHTYN' was revoked!
Mar 18 16:57:50-941047 taler-exchange-httpd-28929 WARNING Revoked denomination `A7PNHTYN' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-948805 taler-exchange-httpd-28929 DEBUG Denomination key `2KJYCNC8' was revoked!
Mar 18 16:57:50-948815 taler-exchange-httpd-28929 WARNING Revoked denomination `2KJYCNC8' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-956601 taler-exchange-httpd-28929 DEBUG Denomination key `W15X1DGQ' was revoked!
Mar 18 16:57:50-956611 taler-exchange-httpd-28929 WARNING Revoked denomination `W15X1DGQ' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-964377 taler-exchange-httpd-28929 DEBUG Denomination key `Z343YA38' was revoked!
Mar 18 16:57:50-964388 taler-exchange-httpd-28929 WARNING Revoked denomination `Z343YA38' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-972108 taler-exchange-httpd-28929 DEBUG Denomination key `FDYZ96M3' was revoked!
Mar 18 16:57:50-972119 taler-exchange-httpd-28929 WARNING Revoked denomination `FDYZ96M3' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-979704 taler-exchange-httpd-28929 DEBUG Denomination key `722J5W9Z' was revoked!
Mar 18 16:57:50-979715 taler-exchange-httpd-28929 WARNING Revoked denomination `722J5W9Z' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-987450 taler-exchange-httpd-28929 DEBUG Denomination key `NMYXVMFW' was revoked!
Mar 18 16:57:50-987459 taler-exchange-httpd-28929 WARNING Revoked denomination `NMYXVMFW' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:50-995273 taler-exchange-httpd-28929 DEBUG Denomination key `C60SRWYC' was revoked!
Mar 18 16:57:50-995282 taler-exchange-httpd-28929 WARNING Revoked denomination `C60SRWYC' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:51-002812 taler-exchange-httpd-28929 DEBUG Denomination key `K95YR04P' was revoked!
Mar 18 16:57:51-002821 taler-exchange-httpd-28929 WARNING Revoked denomination `K95YR04P' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:51-010582 taler-exchange-httpd-28929 DEBUG Denomination key `Y0X6YZSW' was revoked!
Mar 18 16:57:51-010591 taler-exchange-httpd-28929 WARNING Revoked denomination `Y0X6YZSW' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:51-018088 taler-exchange-httpd-28929 DEBUG Denomination key `QABESMF2' was revoked!
Mar 18 16:57:51-018097 taler-exchange-httpd-28929 WARNING Revoked denomination `QABESMF2' unknown (or duplicate file), ignoring revocation
Mar 18 16:57:51-018176 taler-exchange-httpd-28929 DEBUG Found auditor signature for DK `J0Y0FRW1'
Mar 18 16:57:51-018185 taler-exchange-httpd-28929 DEBUG Found auditor signature for DK `Z2A5ZVB9'
Mar 18 16:57:51-018190 taler-exchange-httpd-28929 DEBUG Found auditor signature for DK `QFB83MR6'
Mar 18 16:57:51-018194 taler-exchange-httpd-28929 DEBUG Found auditor signature for DK `1XPSEJEX'
Mar 18 16:57:51-018199 taler-exchange-httpd-28929 DEBUG Found auditor signature for DK `EANAC3Z2'
Mar 18 16:57:51-018209 taler-exchange-httpd-28929 INFO Creating /keys for cherry pick date Thu Jan 01 01:00:00 1970
Mar 18 16:57:51-029306 taler-exchange-httpd-28929 INFO Creating /keys for cherry pick date Mon Mar 18 16:57:49 2019
Mar 18 16:57:51-039951 taler-exchange-httpd-28929 DEBUG KS acquired at TEH_KS_loop (0xb7b21830/1)
Mar 18 16:57:51-846373 taler-exchange-httpd-28929 INFO Handling request for URL '/keys'
Mar 18 16:57:51-846425 taler-exchange-httpd-28929 DEBUG KS acquired at TEH_KS_handler_keys (0xb7b21830/2)
Mar 18 16:57:51-846448 taler-exchange-httpd-28929 INFO Filtering /keys by cherry pick date Thu Jan 01 01:00:00 1970 found entry 0/2
Mar 18 16:57:51-846468 taler-exchange-httpd-28929 DEBUG KS released at TEH_KS_handler_keys (0xb7b21830/2)
Mar 18 16:57:51-846481 taler-exchange-httpd-28929 DEBUG KS release called (0xb7b21830/2)
Mar 18 16:57:51-848974 test-exchange-api-new-twisted-28900 DEBUG Connecting to the exchange (http://localhost:8888/)
Mar 18 16:57:51-849050 test-exchange-api-new-twisted-28900 DEBUG Requesting keys with URL `http://localhost:8888/keys'.
Mar 18 16:57:51-850611 taler-exchange-httpd-28929 INFO Handling request for URL '/keys'
Mar 18 16:57:51-850651 taler-exchange-httpd-28929 DEBUG KS acquired at TEH_KS_handler_keys (0xb7b21830/2)
Mar 18 16:57:51-850671 taler-exchange-httpd-28929 INFO Filtering /keys by cherry pick date Thu Jan 01 01:00:00 1970 found entry 0/2
Mar 18 16:57:51-850685 taler-exchange-httpd-28929 DEBUG KS released at TEH_KS_handler_keys (0xb7b21830/2)
Mar 18 16:57:51-850696 taler-exchange-httpd-28929 DEBUG KS release called (0xb7b21830/2)
Mar 18 16:57:51-852841 test-exchange-api-new-twisted-28900 INFO Received keys from URL `http://localhost:8888/keys' with status 200.
Mar 18 16:57:51-871034 test-exchange-api-new-twisted-28900 DEBUG Crawling DK 'valid_from': Mon Mar 18 16:57:49 2019
Mar 18 16:57:51-878989 test-exchange-api-new-twisted-28900 DEBUG Crawling DK 'valid_from': Mon Mar 18 16:57:49 2019
Mar 18 16:57:51-886984 test-exchange-api-new-twisted-28900 DEBUG Crawling DK 'valid_from': Mon Mar 18 16:57:49 2019
Mar 18 16:57:51-895237 test-exchange-api-new-twisted-28900 DEBUG Crawling DK 'valid_from': Mon Mar 18 16:57:49 2019
Mar 18 16:57:51-903104 test-exchange-api-new-twisted-28900 DEBUG Crawling DK 'valid_from': Mon Mar 18 16:57:49 2019
Mar 18 16:57:51-950809 test-exchange-api-new-twisted-28900 DEBUG Last DK issue date update to: Mon Mar 18 16:57:49 2019
Mar 18 16:57:51-950818 test-exchange-api-new-twisted-28900 DEBUG Updating auditors
Mar 18 16:57:51-950823 test-exchange-api-new-twisted-28900 DEBUG Found new auditor!
Mar 18 16:57:51-950840 test-exchange-api-new-twisted-28900 INFO Connecting to auditor at URL `http://the.auditor/'.
Mar 18 16:57:51-950848 test-exchange-api-new-twisted-28900 DEBUG Got 5 DK from /keys in generation 1
Mar 18 16:57:51-950886 test-exchange-api-new-twisted-28900 INFO Starting Fakebank on port 8082 (localhost:8082)
Mar 18 16:57:51-950947 test-exchange-api-new-twisted-28900 DEBUG Running command `refresh-reveal-409-conflict'
Mar 18 16:57:51-950955 test-exchange-api-new-twisted-28900 DEBUG Running batched command: refresh-create-reserve
Mar 18 16:57:51-958609 test-exchange-api-new-twisted-28900 INFO Requesting auditor version with URL `http://the.auditor/version'.
Mar 18 16:57:51-959928 test-exchange-api-new-twisted-28900 DEBUG Making transfer from 62 to 2 over EUR:5.01 and subject 0TZBG72ZN9E4TAXAGB5EJ9N74CM952F95E3VV175KQD1Z9G40A20
Mar 18 16:57:51-959947 test-exchange-api-new-twisted-28900 INFO Receiving incoming wire transfer: 62->2, subject: 0TZBG72ZN9E4TAXAGB5EJ9N74CM952F95E3VV175KQD1Z9G40A20, amount: EUR:5.01, from http://localhost:8888/
Mar 18 16:57:51-960043 test-exchange-api-new-twisted-28900 DEBUG Running command `refresh-reveal-409-conflict'
Mar 18 16:57:51-960053 test-exchange-api-new-twisted-28900 DEBUG Running batched command: wirewatch
Mar 18 16:57:51-969344 taler-exchange-wirewatch-28970 DEBUG Checking for incoming wire transfers
Mar 18 16:57:51-978882 taler-exchange-wirewatch-28970 DEBUG Starting transaction on 0xb960da00
Mar 18 16:57:51-979392 taler-exchange-wirewatch-28970 DEBUG Delta: -1024
Mar 18 16:57:51-980658 test-exchange-api-new-twisted-28900 INFO Client asked for up to -1024 results of type credit for account 2 starting at 0
Mar 18 16:57:51-980683 test-exchange-api-new-twisted-28900 INFO Found transaction over EUR:5.01 from 62 to 2
Mar 18 16:57:51-980811 taler-exchange-wirewatch-28970 DEBUG Got history callback, direction 1!
Mar 18 16:57:51-980842 taler-exchange-wirewatch-28970 INFO Adding wire transfer over EUR:5.01 with (hashed) subject `5BBME8A9'
Mar 18 16:57:51-980850 taler-exchange-wirewatch-28970 INFO Plain text subject (= reserve_pub): 0TZBG72ZN9E4TAXAGB5EJ9N74CM952F95E3VV175KQD1Z9G40A20
Mar 18 16:57:51-981121 taler-exchange-wirewatch-28970 INFO Creating reserve 5BBME8A9 with expiration in 28 days
Mar 18 16:57:51-981133 taler-exchange-wirewatch-28970 DEBUG Reserve does not exist; creating a new one
Mar 18 16:57:51-981761 taler-exchange-wirewatch-28970 DEBUG Got history callback, direction 0!
Mar 18 16:57:51-981769 taler-exchange-wirewatch-28970 DEBUG End of list. Committing progress!
Mar 18 16:57:51-982983 taler-exchange-wirewatch-28970 INFO Shutdown due to test mode!
Mar 18 16:57:51-983662 test-exchange-api-new-twisted-28900 DEBUG Got SIGCHLD for `wirewatch'.
Mar 18 16:57:51-983688 test-exchange-api-new-twisted-28900 DEBUG Got the dead child process handle, waiting for termination ...
Mar 18 16:57:51-983705 test-exchange-api-new-twisted-28900 DEBUG ... definitively terminated
Mar 18 16:57:51-983713 test-exchange-api-new-twisted-28900 DEBUG Dead child, go on with next command.
Mar 18 16:57:51-983724 test-exchange-api-new-twisted-28900 DEBUG Running command `refresh-reveal-409-conflict'
Mar 18 16:57:51-983732 test-exchange-api-new-twisted-28900 DEBUG Running batched command: refresh-withdraw-coin
* Found bundle for host localhost: 0xb9371a70 [can pipeline]
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (127.0.0.1) port 8081 (#0)
> POST /reserve/withdraw HTTP/1.1
Host: localhost:8888
Accept-Encoding: deflate
Accept: */*
Content-Type: application/json
Content-Length: 919

* We are completely uploaded and fine
Mar 18 16:57:52-003544 taler-exchange-httpd-28929 INFO Handling request for URL '/reserve/withdraw'
Mar 18 16:57:52-003586 taler-exchange-httpd-28929 INFO Handling request for URL '/reserve/withdraw'
Mar 18 16:57:52-003595 taler-exchange-httpd-28929 INFO Handling request for URL '/reserve/withdraw'
Mar 18 16:57:52-003646 taler-exchange-httpd-28929 DEBUG KS acquired at TEH_RESERVE_handler_reserve_withdraw (0xb7b21830/2)
Mar 18 16:57:52-003689 taler-exchange-httpd-28929 DEBUG Looking for denom: 'M8FTEZXG..'
Mar 18 16:57:52-023374 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb160d090
Mar 18 16:57:52-024033 taler-exchange-httpd-28929 INFO Trying to withdraw from reserve: 0TZBG72ZN9E4TAXAGB5EJ9N74CM952F95E3VV175KQD1Z9G40A20
Mar 18 16:57:52-026231 taler-exchange-httpd-28929 DEBUG KS released at TEH_RESERVE_handler_reserve_withdraw (0xb7b21830/2)
Mar 18 16:57:52-026245 taler-exchange-httpd-28929 DEBUG KS release called (0xb7b21830/2)
< HTTP/1.1 200 OK
< Connection: Keep-Alive
< Content-Length: 333
< Content-Encoding: deflate
< Content-Type: application/json
< Date: Mon, 18 Mar 2019 15:57:52 GMT
< 
* Curl_http_done: called premature == 0
* Connection #0 to host localhost left intact
Mar 18 16:57:52-027860 test-exchange-api-new-twisted-28900 DEBUG Running command `refresh-reveal-409-conflict'
Mar 18 16:57:52-027876 test-exchange-api-new-twisted-28900 DEBUG Running batched command: refresh-deposit-partial
Mar 18 16:57:52-058938 test-exchange-api-new-twisted-28900 DEBUG URL for deposit: `http://localhost:8888/deposit'
* Found bundle for host localhost: 0xb9371a70 [can pipeline]
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (127.0.0.1) port 8081 (#0)
> POST /deposit HTTP/1.1
Host: localhost:8888
Accept-Encoding: deflate
Accept: */*
Content-Type: application/json
Content-Length: 1729
Expect: 100-continue

Mar 18 16:57:52-059116 taler-exchange-httpd-28929 INFO Handling request for URL '/deposit'
< HTTP/1.1 100 Continue
* We are completely uploaded and fine
Mar 18 16:57:52-059179 taler-exchange-httpd-28929 INFO Handling request for URL '/deposit'
Mar 18 16:57:52-059190 taler-exchange-httpd-28929 INFO Handling request for URL '/deposit'
Mar 18 16:57:52-059330 taler-exchange-httpd-28929 DEBUG KS acquired at TEH_DEPOSIT_handler_deposit (0xb7b21830/2)
Mar 18 16:57:52-059361 taler-exchange-httpd-28929 DEBUG Looking for denom: 'M8FTEZXG..'
Mar 18 16:57:52-059656 taler-exchange-httpd-28929 DEBUG KS released at TEH_DEPOSIT_handler_deposit (0xb7b21830/2)
Mar 18 16:57:52-059664 taler-exchange-httpd-28929 DEBUG KS release called (0xb7b21830/2)
Mar 18 16:57:52-059670 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb160d090
Mar 18 16:57:52-059743 taler-exchange-httpd-28929 DEBUG Getting known coin data for coin S911S51X
Mar 18 16:57:52-060123 taler-exchange-httpd-28929 DEBUG Creating known coin S911S51X
Mar 18 16:57:52-069662 taler-exchange-httpd-28929 DEBUG KS acquired at verify_and_execute_deposit (0xb7b21830/2)
Mar 18 16:57:52-069703 taler-exchange-httpd-28929 DEBUG Looking for denom: 'M8FTEZXG..'
Mar 18 16:57:52-069710 taler-exchange-httpd-28929 DEBUG KS released at verify_and_execute_deposit (0xb7b21830/2)
Mar 18 16:57:52-069715 taler-exchange-httpd-28929 DEBUG KS release called (0xb7b21830/2)
Mar 18 16:57:52-069720 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb160d090
Mar 18 16:57:52-069833 taler-exchange-httpd-28929 DEBUG Getting deposits for coin S911S51X
Mar 18 16:57:52-070218 taler-exchange-httpd-28929 DEBUG Getting transactions for coin S911S51X
Mar 18 16:57:52-071258 taler-exchange-httpd-28929 INFO Inserting deposit to be executed at Mon Mar 18 16:57:52 2019 (1552924672000000/0)
Mar 18 16:57:52-072772 taler-exchange-httpd-28929 DEBUG KS acquired at TEH_KS_sign (0xb7b21830/2)
Mar 18 16:57:52-083467 taler-exchange-httpd-28929 DEBUG KS released at TEH_KS_sign (0xb7b21830/2)
Mar 18 16:57:52-083476 taler-exchange-httpd-28929 DEBUG KS release called (0xb7b21830/2)
< HTTP/1.1 200 OK
< Connection: Keep-Alive
< Content-Length: 185
< Content-Encoding: deflate
< Content-Type: application/json
< Date: Mon, 18 Mar 2019 15:57:52 GMT
< 
* Curl_http_done: called premature == 0
* Connection #0 to host localhost left intact
Mar 18 16:57:52-091872 test-exchange-api-new-twisted-28900 DEBUG Running command `refresh-reveal-409-conflict'
Mar 18 16:57:52-091888 test-exchange-api-new-twisted-28900 DEBUG Running batched command: refresh-melt
Mar 18 16:57:52-200924 test-exchange-api-new-twisted-28900 INFO Received version from URL `http://the.auditor/version' with status 0.
* Found bundle for host localhost: 0xb9371a70 [can pipeline]
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (127.0.0.1) port 8081 (#0)
> POST /refresh/melt HTTP/1.1
Host: localhost:8888
Accept-Encoding: deflate
Accept: */*
Content-Type: application/json
Content-Length: 1313
Expect: 100-continue

Mar 18 16:57:52-201051 taler-exchange-httpd-28929 INFO Handling request for URL '/refresh/melt'
< HTTP/1.1 100 Continue
* We are completely uploaded and fine
Mar 18 16:57:52-201159 taler-exchange-httpd-28929 INFO Handling request for URL '/refresh/melt'
Mar 18 16:57:52-201174 taler-exchange-httpd-28929 INFO Handling request for URL '/refresh/melt'
Mar 18 16:57:52-201539 taler-exchange-httpd-28929 DEBUG KS acquired at TEH_REFRESH_handler_refresh_melt (0xb7b21830/2)
Mar 18 16:57:52-201569 taler-exchange-httpd-28929 DEBUG Looking for denom: 'M8FTEZXG..'
Mar 18 16:57:52-201577 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb160d090
Mar 18 16:57:52-201692 taler-exchange-httpd-28929 DEBUG Getting known coin data for coin S911S51X
Mar 18 16:57:52-203285 test-exchange-api-new-twisted-28900 INFO Requesting auditor version with URL `http://the.auditor/version'.
Mar 18 16:57:52-209776 test-exchange-api-new-twisted-28900 INFO Received version from URL `http://the.auditor/version' with status 0.
Mar 18 16:57:52-211513 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb160d090
Mar 18 16:57:52-211705 taler-exchange-httpd-28929 DEBUG Getting transactions for coin S911S51X
Mar 18 16:57:52-212086 taler-exchange-httpd-28929 DEBUG Getting known coin data for coin S911S51X
Mar 18 16:57:52-214313 taler-exchange-httpd-28929 DEBUG KS acquired at TEH_KS_sign (0xb7b21830/3)
Mar 18 16:57:52-215392 test-exchange-api-new-twisted-28900 INFO Requesting auditor version with URL `http://the.auditor/version'.
Mar 18 16:57:52-219707 test-exchange-api-new-twisted-28900 INFO Received version from URL `http://the.auditor/version' with status 0.
Mar 18 16:57:52-225267 taler-exchange-httpd-28929 DEBUG KS released at TEH_KS_sign (0xb7b21830/3)
Mar 18 16:57:52-225279 taler-exchange-httpd-28929 DEBUG KS release called (0xb7b21830/3)
Mar 18 16:57:52-225361 taler-exchange-httpd-28929 DEBUG KS released at TEH_REFRESH_handler_refresh_melt (0xb7b21830/2)
Mar 18 16:57:52-225368 taler-exchange-httpd-28929 DEBUG KS release called (0xb7b21830/2)
< HTTP/1.1 200 OK
< Connection: Keep-Alive
< Content-Length: 197
< Content-Encoding: deflate
< Content-Type: application/json
< Date: Mon, 18 Mar 2019 15:57:52 GMT
< 
* Curl_http_done: called premature == 0
* Connection #0 to host localhost left intact
Mar 18 16:57:52-233620 test-exchange-api-new-twisted-28900 DEBUG Running command `refresh-reveal-409-conflict'
Mar 18 16:57:52-233634 test-exchange-api-new-twisted-28900 DEBUG Running batched command: flip-upload
Mar 18 16:57:52-233893 test-exchange-api-new-twisted-28900 INFO Requesting auditor version with URL `http://the.auditor/version'.
Mar 18 16:57:52-238000 test-exchange-api-new-twisted-28900 DEBUG Got SIGCHLD for `flip-upload'.
Mar 18 16:57:52-238021 test-exchange-api-new-twisted-28900 DEBUG Got the dead child process handle, waiting for termination ...
Mar 18 16:57:52-238033 test-exchange-api-new-twisted-28900 DEBUG ... definitively terminated
Mar 18 16:57:52-238038 test-exchange-api-new-twisted-28900 DEBUG Dead child, go on with next command.
Mar 18 16:57:52-238047 test-exchange-api-new-twisted-28900 DEBUG Running command `refresh-reveal-409-conflict'
Mar 18 16:57:52-238052 test-exchange-api-new-twisted-28900 DEBUG Running batched command: refresh-(flipped-)reveal
Mar 18 16:57:52-257871 test-exchange-api-new-twisted-28900 INFO Received version from URL `http://the.auditor/version' with status 0.
* Found bundle for host localhost: 0xb9371a70 [can pipeline]
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (127.0.0.1) port 8081 (#0)
> POST /refresh/reveal HTTP/1.1
Host: localhost:8888
Accept-Encoding: deflate
Accept: */*
Content-Type: application/json
Content-Length: 1597
Expect: 100-continue

Mar 18 16:57:52-258120 taler-exchange-httpd-28929 INFO Handling request for URL '/refresh/reveal'
< HTTP/1.1 100 Continue
* We are completely uploaded and fine
Mar 18 16:57:52-258207 taler-exchange-httpd-28929 INFO Handling request for URL '/refresh/reveal'
Mar 18 16:57:52-258223 taler-exchange-httpd-28929 INFO Handling request for URL '/refresh/reveal'
Mar 18 16:57:52-258277 taler-exchange-httpd-28929 DEBUG KS acquired at handle_refresh_reveal_json (0xb7b21830/2)
Mar 18 16:57:52-270734 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb160d090
Mar 18 16:57:52-271224 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb160d090
Mar 18 16:57:52-288337 test-exchange-api-new-twisted-28900 INFO Requesting auditor version with URL `http://the.auditor/version'.
Mar 18 16:57:52-292681 test-exchange-api-new-twisted-28900 INFO Received version from URL `http://the.auditor/version' with status 0.
Mar 18 16:57:52-316271 taler-exchange-httpd-28929 DEBUG Starting transaction on 0xb160d090
Mar 18 16:57:52-318926 taler-exchange-httpd-28929 DEBUG KS released at handle_refresh_reveal_json (0xb7b21830/2)
Mar 18 16:57:52-318944 taler-exchange-httpd-28929 DEBUG KS release called (0xb7b21830/2)
< HTTP/1.1 200 OK
< Connection: Keep-Alive
< Content-Length: 1065
< Content-Encoding: deflate
< Content-Type: application/json
< Date: Mon, 18 Mar 2019 15:57:52 GMT
< 
* Curl_http_done: called premature == 0
* Connection #0 to host localhost left intact
Mar 18 16:57:52-338628 test-exchange-api-new-twisted-28900 ERROR Unexpected response code 200/0 to command refresh-reveal-409-conflict in testing_api_cmd_refresh.c:324
{"ev_sigs": [{"ev_sig": "51SPJSSDESGPR80A40M74WV140520818ECG26CHK88TKCHHN6CRKECT588TMCDSK75348DT160T3JDHK6GS34CA17113AC9P64V4ACJ574S4ACHQ8H2M2HHK89148DHS6X2K0C9S8RV4ACT56MVMCE1P8N1KEGT174W4AH9K6S238GHM6D23CGSR8H2KAG9G650K8DT484W32H1G6MV38CSM8GR48CHJ71144D226GV4CE248CRKGCSP750KGC9Q88W4CC1S68SKAGHM71148DHS74V3JGSM8MWKGDA56X1K2G9N64VK8HHQ8D2MCH1P70W4AC1Q60R32CT28CR3CGA36H1MADA564T44DSM60SM2DSS8S144GHQ68W48E1M6RTMCHHP650KACSQ64T38HJ288S32E1R60S42EA18H0K6C9P6WRKAH2569148D935452081918G2J2G0"}, {"ev_sig": "51SPJSSDESGPR80A40M74WV140520818ECG26DHR6X330GSQ6MRK8GT6851K4DSQ89230GT16133AD9M8D130HJ56CV36CT46534ADJ174R44EA474VKJH226CSK2CSG68T30CA26MR3GHJ374TK0DHN6D2KJC1P6CSM8H1G8MWK6G9G8MS46D1G6GRKAGHM6WWK6EA56WV44GHN892M6GHM6N348HHS612K0GSP60V3CHHP74V42GHS68VM4E1H64TKJG9P68T32H1R8D138D9R6GV30H9K74R3CCJ16GV3GDHJ851K2DJ16N234C248MW4CDT26S1K4GA48N1M2D1M8CW36DT56WS46H1P8N1KGD1M6CSKJCHK6WVK6GJ564TKAGSP6514CGA56CRM4C1Q6GTK8C1G6WW44C1M64SKCD1M6CSMCGT274T3GCH35452081918G2J2G0"}, {"ev_sig": "51SPJSSDESGPR80A40M74WV140520818ECG26D9J6N0M6GT5711K8HA288VM8E2184R38E2264RM2E9R8CTK6E2360VKGD1K6S142CT28MS34C2368VMCH1K8S1MCCHP68T3AG9M88TK4DJ28S23JGHQ6MW4CC1P88RKJEA18RVK4DHH64R44E1N6X234HHK6GWM4E1M6GTM2GA574RM4DHJ8MWMCEA58H0K2E1M6GW3ED2688SK6DHK6CTK6H9J8H2K4HHS6N1K2C1H6MTMAGT160S3JHHH712K6H258GVM2CA5691MAGA48N2K8DT2692M4E9R8GTK8D246H230G9Q8MSMCD9K6H248H1Q8GV48G9G692KCD9S60VM2CHJ6GV3AE226133CH1R8RSK2H1K60VM4HHQ6H1K8CJ684T44D1P8N2MAE9G8CW3GH135452081918G2J2G0"}, {"ev_sig": "51SPJSSDESGPR80A40M74WV140520818ECG26CJ569234D1G650KGD1K892KGC9K8N14CE1J64R48C9S88TK6GT68RSMACHQ8RV3GCHP8N1KAC1J8H2MAGHK6X2K2D1H8CR32D226MTK0D9P8GV44HJ56RSM2HHM6S1K4GJ18D0K2DHM70T30CT260T44D9P6GTM6GHN74RM6CT48GVK8HJ47134CC216GWK6CHJ6N14CGSP6X230D226RTK6EA16CVK6GSM6MWM4C1S68V30C236GW34DHH7123ED9J6MS30E1K74VK8H246WWMAGSS6GWKAE228N2K6D1P74V3AHHP8MTK4GHS6X234HA66WS3EGT36N1KADA66WWKCDHN851K2GJ66RVK6GT2711M8GA56GTKCCT28N342DA46MS3ACHK6D344C1Q64SM2GH35452081918G2J2G0"}]}Mar 18 16:57:52-338732 test-exchange-api-new-twisted-28900 ERROR Failed at command `refresh-reveal-409-conflict'
Mar 18 16:57:52-338739 test-exchange-api-new-twisted-28900 ERROR Batch is at command `refresh-(flipped-)reveal'
Mar 18 16:57:52-338760 test-exchange-api-new-twisted-28900 INFO Executing shutdown at `refresh-reveal-409-conflict'
Mar 18 16:57:52-338774 test-exchange-api-new-twisted-28900 DEBUG Disconnecting the exchange
Mar 18 16:57:52-338785 test-exchange-api-new-twisted-28900 DEBUG Disconnecting the auditor `http://the.auditor/'
Mar 18 16:57:52-339421 taler-exchange-httpd-28929 DEBUG KS released at TEH_KS_free (0xb7b21830/1)
Mar 18 16:57:52-339441 taler-exchange-httpd-28929 DEBUG KS release called (0xb7b21830/1)
FAIL test_exchange_api_twisted (exit status: 1)
test_exchange_api_twisted.log (29,085 bytes)   

Marcello Stanisci

2019-05-20 16:15

reporter   ~0014414

Another "episode" in this story.

This bug suddenly reappeared on Gv 90% of the times, until the Twister got updated to
this version: 65bd48c64d3034530b2c. After the update, the bug disappeared!

Under the assumption that the version mentioned above fixed it up, the practical fix can
be found in this command's output (diff between the latest failing commit and the first successful):

  git diff 730cc0c1a80c7ba10b6a1 65bd48c64d3034530b2c

One of the substantial changes shown in this diff, is the introduction of more machine
states that made the Twister STOP sharing the "upload state" between the client's and
Twister's uploads. Before the change, it was possible for the Twister to be in the "upload state"
and not being able to tell whether the upload was from the client or to the proxied service!

Moreover, this might explain the aleatory nature of this bug, because that state overlapping
(therefore the unpredicatble behaviour) was aleatory as well.

That said, let's keep this open.

Marcello Stanisci

2019-06-04 13:57

reporter   ~0014505

Still there: https://buildbot.taler.net/#/builders/1/builds/120

Possibly, due to the changes introduced by 0005724.

Christian Grothoff

2020-03-22 21:28

manager   ~0015463

I've again not seen this for a while, and there were extensive exchange changes in the meantime. Marking resolved for now.

Issue History

Date Modified Username Field Change
2019-02-14 14:00 Christian Grothoff New Issue
2019-02-14 14:00 Christian Grothoff Status new => assigned
2019-02-14 14:00 Christian Grothoff Assigned To => Marcello Stanisci
2019-02-14 14:02 Christian Grothoff Reproducibility have not tried => random
2019-02-14 14:02 Christian Grothoff Additional Information Updated
2019-02-14 14:02 Christian Grothoff Note Added: 0013761
2019-02-14 17:05 Marcello Stanisci Note Added: 0013777
2019-02-14 21:28 Christian Grothoff Note Added: 0013785
2019-02-15 17:04 Marcello Stanisci Note Added: 0013795
2019-03-18 17:13 Marcello Stanisci File Added: test_exchange_api_twisted.log
2019-03-18 17:13 Marcello Stanisci Note Added: 0014217
2019-05-20 16:15 Marcello Stanisci Note Added: 0014414
2019-06-04 13:57 Marcello Stanisci Note Added: 0014505
2019-12-18 23:29 Christian Grothoff Target Version 0.6 => 0.7.1
2020-03-22 21:28 Christian Grothoff Note Added: 0015463
2020-03-22 21:28 Christian Grothoff Assigned To Marcello Stanisci => Christian Grothoff
2020-03-22 21:28 Christian Grothoff Status assigned => resolved
2020-03-22 21:28 Christian Grothoff Resolution open => fixed
2020-03-22 21:28 Christian Grothoff Fixed in Version => 0.6
2020-03-24 01:08 Christian Grothoff Fixed in Version 0.6 => 0.7.0
2020-03-24 01:08 Christian Grothoff Target Version 0.7.1 => 0.7.0
2020-03-31 16:04 Christian Grothoff Status resolved => closed