View Issue Details

IDProjectCategoryView StatusLast Update
0004737Talerexchangepublic2016-11-20 03:26
ReporterFlorian DoldAssigned ToChristian Grothoff 
PriorityurgentSeverityblockReproducibilityhave not tried
Status closedResolutionfixed 
Product VersionSVN HEAD 
Target Version0.2Fixed in Version0.2 
Summary0004737: taler-exchange-httpd-31723 ERROR Query failed at plugin_exchangedb_postgres.c:1966
DescriptionHappens when withdrawing to test.taler.net right now ...
Additional InformationOct 17 23:22:20-552655 taler-exchange-httpd-31723 INFO Handling request for URL '/reserve/status'
Oct 17 23:22:20-552936 taler-exchange-httpd-31723 ERROR Query failed at plugin_exchangedb_postgres.c:1966: ERROR: current transaction is aborted, commands ignored until end of transaction block
 (PGRES_FATAL_ERROR)
TagsNo tags attached.

Activities

Florian Dold

2016-10-17 23:26

manager   ~0011333

Adding Marcello, maybe this was caused by recent DB changes?

Florian Dold

2016-10-17 23:27

manager   ~0011334

Restarting the exchange fixed this. Would still be interesting to know where this came from ....

Marcello Stanisci

2016-10-18 17:36

manager   ~0011344

That's unlikely to be, if you refer to 0004709, because those functions get never called so far; exchangedb's testcase also passed ...

Christian Grothoff

2016-10-22 18:01

manager   ~0011376

Ok, so docs suggests this happens if we ignore an error from an SQL query and then try to keep going with the next transaction (without aborting the previous one). So this suggests our DB error handling is not quite right _somewhere_.

To diagnose this, it would be good to know the operations the exchange did *before* the error happens, the line where the error is report is just the symptom, not the cause. So we probably will need logging on ALL DB statements so we can trace it back to the one that is at fault.

Christian Grothoff

2016-10-24 09:48

manager   ~0011379

I've added new logging to GNUnet (SVN 38192) to help diagnose the issue.

Please run the exchange using (possibly among others) the environment variable

GNUNET_FORCE_LOG=";pq.c;;;DEBUG/;postgres.c;;;DEBUG/"

to ensure DEBUG-level logging for postgres SQL executions. If the problem re-occurs, the resulting log ought to be helpful.

(Assigning to Marcello: please put the instrumentation (see above) into place and monitor for the bug to re-appear. Once the environment variable is set correctly, you should immediately see a few DEBUG-level log statements about prepared statements on startup of the exchange; note that you do have to recompile GNUnet.)

Marcello Stanisci

2016-10-24 11:29

manager   ~0011380

Recompiling gnunet+exchange gave the following error:

==23784== Process terminating with default action of signal 11 (SIGSEGV)
==23784== Access not within mapped region at address 0x1
==23784== at 0x4C2DDA2: strlen (vg_replace_strmem.c:454)
==23784== by 0x5D38DA2: vfprintf (vfprintf.c:1637)
==23784== by 0x5D5FE58: vsnprintf (vsnprintf.c:114)
==23784== by 0x565F46A: GNUNET_asprintf (common_allocation.c:476)
==23784== by 0x5445A4B: extract_amount (pq_result_helper.c:227)
==23784== by 0xAE378FE: GNUNET_PQ_extract_result (pq.c:147)
==23784== by 0xAC2D48D: postgres_select_reserves_in_above_serial_id (plugin_exchangedb_postgres.c:4694)
==23784== by 0x406CD0: run (test_exchangedb.c:1324)
==23784== by 0x5693D95: run_ready (scheduler.c:620)
==23784== by 0x5693D95: GNUNET_SCHEDULER_run (scheduler.c:887)
==23784== by 0x409F10: main (test_exchangedb.c:1671)

Marcello Stanisci

2016-10-24 11:30

manager   ~0011381

Done as 'test-green' user.

Marcello Stanisci

2016-10-24 12:10

manager   ~0011382

Ah, I got that by running testcases in exchangedb/. To be precise, by manually running (via valgrind) exchangedb/.libs/test-exchangedb-postgres.

Christian Grothoff

2016-10-24 12:41

manager   ~0011383

The crash is fixed in b8245d7..ddb5987

Marcello Stanisci

2016-10-24 17:25

manager   ~0011384

Env var set (and tested) in 4fc31f6 (deployment repo)

Christian Grothoff

2016-11-17 11:32

manager   ~0011513

Found "the" non-completed transaction that needed proper abort. Fixed in 2e16fbb..bd096d3

Issue History

Date Modified Username Field Change
2016-10-17 23:25 Florian Dold New Issue
2016-10-17 23:25 Florian Dold Status new => assigned
2016-10-17 23:25 Florian Dold Assigned To => Christian Grothoff
2016-10-17 23:26 Florian Dold Note Added: 0011333
2016-10-17 23:27 Florian Dold Note Added: 0011334
2016-10-17 23:27 Florian Dold Status assigned => feedback
2016-10-18 17:36 Marcello Stanisci Note Added: 0011344
2016-10-22 18:01 Christian Grothoff Note Added: 0011376
2016-10-24 09:44 Christian Grothoff Assigned To Christian Grothoff => Marcello Stanisci
2016-10-24 09:44 Christian Grothoff Status feedback => assigned
2016-10-24 09:48 Christian Grothoff Note Added: 0011379
2016-10-24 11:29 Marcello Stanisci Note Added: 0011380
2016-10-24 11:30 Marcello Stanisci Note Added: 0011381
2016-10-24 12:10 Marcello Stanisci Note Added: 0011382
2016-10-24 12:41 Christian Grothoff Note Added: 0011383
2016-10-24 17:25 Marcello Stanisci Note Added: 0011384
2016-11-15 15:58 Christian Grothoff Product Version => SVN HEAD
2016-11-15 15:58 Christian Grothoff Target Version => 0.2
2016-11-17 11:32 Christian Grothoff Note Added: 0011513
2016-11-17 11:37 Christian Grothoff Assigned To Marcello Stanisci => Christian Grothoff
2016-11-17 11:37 Christian Grothoff Status assigned => resolved
2016-11-17 11:37 Christian Grothoff Resolution open => fixed
2016-11-17 11:37 Christian Grothoff Fixed in Version => 0.2
2016-11-20 03:26 Christian Grothoff Status resolved => closed