View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0004737 | Taler | exchange | public | 2016-10-17 21:25 | 2016-11-20 02:26 |
| Reporter | Florian Dold | Assigned To | Christian Grothoff | Resolution deadline | |
| Implementer | Reviewer | ||||
| Release signed by | Deployed by | ||||
| Verifier | Communicator | ||||
| Data protection authority notification required | No | ||||
| CSIRT notification required | No | ||||
| Estimated effort (hours) | Actual effort (hours) | 0 | |||
| Fast-track | No | ||||
| Work package | none | ||||
| Priority | urgent | Severity | block | Reproducibility | have not tried |
| Status | closed | Resolution | fixed | ||
| Product Version | git (master) | ||||
| Target Version | 0.2 | Fixed in Version | 0.2 | ||
| Summary | 0004737: taler-exchange-httpd-31723 ERROR Query failed at plugin_exchangedb_postgres.c:1966 | ||||
| Description | Happens when withdrawing to test.taler.net right now ... | ||||
| Additional Information | Oct 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) | ||||
| Tags | No tags attached. | ||||
| Adding Marcello, maybe this was caused by recent DB changes? | |
| Restarting the exchange fixed this. Would still be interesting to know where this came from .... | |
| That's unlikely to be, if you refer to 0004709, because those functions get never called so far; exchangedb's testcase also passed ... | |
| 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. | |
| 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.) | |
| 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) | |
| Done as 'test-green' user. | |
| Ah, I got that by running testcases in exchangedb/. To be precise, by manually running (via valgrind) exchangedb/.libs/test-exchangedb-postgres. | |
| The crash is fixed in b8245d7..ddb5987 | |
| Env var set (and tested) in 4fc31f6 (deployment repo) | |
| Found "the" non-completed transaction that needed proper abort. Fixed in 2e16fbb..bd096d3 | |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2016-10-17 21:25 | Florian Dold | New Issue | |
| 2016-10-17 21:25 | Florian Dold | Status | new => assigned |
| 2016-10-17 21:25 | Florian Dold | Assigned To | => Christian Grothoff |
| 2016-10-17 21:26 | Florian Dold | Note Added: 0011333 | |
| 2016-10-17 21:27 | Florian Dold | Note Added: 0011334 | |
| 2016-10-17 21:27 | Florian Dold | Status | assigned => feedback |
| 2016-10-18 15:36 | Marcello Stanisci | Note Added: 0011344 | |
| 2016-10-22 16:01 | Christian Grothoff | Note Added: 0011376 | |
| 2016-10-24 07:44 | Christian Grothoff | Assigned To | Christian Grothoff => Marcello Stanisci |
| 2016-10-24 07:44 | Christian Grothoff | Status | feedback => assigned |
| 2016-10-24 07:48 | Christian Grothoff | Note Added: 0011379 | |
| 2016-10-24 09:29 | Marcello Stanisci | Note Added: 0011380 | |
| 2016-10-24 09:30 | Marcello Stanisci | Note Added: 0011381 | |
| 2016-10-24 10:10 | Marcello Stanisci | Note Added: 0011382 | |
| 2016-10-24 10:41 | Christian Grothoff | Note Added: 0011383 | |
| 2016-10-24 15:25 | Marcello Stanisci | Note Added: 0011384 | |
| 2016-11-15 14:58 | Christian Grothoff | Product Version | => git (master) |
| 2016-11-15 14:58 | Christian Grothoff | Target Version | => 0.2 |
| 2016-11-17 10:32 | Christian Grothoff | Note Added: 0011513 | |
| 2016-11-17 10:37 | Christian Grothoff | Assigned To | Marcello Stanisci => Christian Grothoff |
| 2016-11-17 10:37 | Christian Grothoff | Status | assigned => informing |
| 2016-11-17 10:37 | Christian Grothoff | Resolution | open => fixed |
| 2016-11-17 10:37 | Christian Grothoff | Fixed in Version | => 0.2 |
| 2016-11-20 02:26 | Christian Grothoff | Status | informing => closed |