View Issue Details

IDProjectCategoryView StatusLast Update
0005566Talerexchangepublic2019-06-04 13:57
ReporterChristian GrothoffAssigned ToMarcello Stanisci 
PrioritynormalSeveritymajorReproducibilityrandom
Status assignedResolutionopen 
Platformi7OSDebian GNU/LinuxOS Versionsqueeze
Product VersionSVN HEAD 
Target Version0.6Fixed in Version 
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.

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

manager   ~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

manager   ~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

manager   ~0014217

Attaching logs from a failing session, again not easily reproducible.

test_exchange_api_twisted.log (29,085 bytes)

Marcello Stanisci

2019-05-20 16:15

manager   ~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

manager   ~0014505

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

Possibly, due to the changes introduced by 0005724.

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 View Revisions
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