Closed fish-sammy closed 8 months ago
rippled ledger_current
gives me
ripple@xrp:/# rippled ledger_current
Loading: "/etc/opt/ripple/rippled.cfg"
2019-Aug-01 16:20:41.538784645 HTTPClient:WRN Warning: No peer protocol configured
2019-Aug-01 16:20:41.538843760 HTTPClient:NFO Connecting to 127.0.0.1:9091
{
"result" : {
"ledger_current_index" : 21474436,
"status" : "success"
}
}
so I cannot see it being a problem of online_delete
having already pruned data in the ledger.
At first I wondered if this might be similar to #2597, but on further testing, I don't think so. I can get the transaction in question from Ripple's public test net server using tx so it's not something about the transaction itself that makes it consistently un-requestable.
Definitely weird, and this may be hard to track down unless we can find a way to reproduce on another server.
(Note: the testnet link I posted above will stop working when ledger 21474047 gets online-deleted from Ripple's public test net servers. AFAIK there are no full-history test net servers.)
@mDuo13 Unfortunately, I don't know how to reproduce it. I experienced the same issue with two different transactions (including the one above that I reported) yesterday and both times restarting the node solved the problem for me. It's definitely still a bug as restarting is not ideal and some differences in the logic of those two RPC calls are causing this problem.
I have also encountered a similar error, seems to only affect transactions processed while the rippled server was stopped/restarting.
The transaction is never picked up by client. I assume I don't have a copy of that ledger index so I perform a ledger_request for the affected ledger:
the transaction does appear on xrp charts
./rippled ledger_request 49685691
Loading: "/rippled.cfg"
2019-Aug-30 05:00:52.277122508 HTTPClient:WRN Warning: No peer protocol configured
2019-Aug-30 05:00:52.277161102 HTTPClient:NFO Connecting to 127.0.0.1:5005
{
"result" : {
"ledger" : {
"accepted" : true,
"account_hash" : "271CC568A8E837589B7898323B07CA76CB8B4344E27A0C19CB850171D4969B77",
"close_flags" : 0,
"close_time" : 620446750,
"close_time_human" : "2019-Aug-30 02:19:10.000000000",
"close_time_resolution" : 10,
"closed" : true,
"hash" : "DD48213B09AC50E21BD7AEE997A7A3EA11BC0A16C466307E43A786919514C65F",
"ledger_hash" : "DD48213B09AC50E21BD7AEE997A7A3EA11BC0A16C466307E43A786919514C65F",
"ledger_index" : "49685691",
"parent_close_time" : 620446742,
"parent_hash" : "2CE9C1CB6F163449A2E445EDE12378D597D4ED25EC55B28CF8ED7A303812FD72",
"seqNum" : "49685691",
"totalCoins" : "99991358133762978",
"total_coins" : "99991358133762978",
"transaction_hash" : "E3A23BBB8ED3CB2211E8C83F191A3165F14133F91E53E0957773844E00F19793"
},
"ledger_index" : 49685691,
"status" : "success"
}
}
But the transaction still isn't found by rippled.
./rippled -- tx AF24700729D1D68382FCD0506BE902B8562D90056F754210E200BC763DACBAD4
Loading: "/rippled.cfg"
2019-Aug-30 05:01:36.007717527 HTTPClient:WRN Warning: No peer protocol configured
2019-Aug-30 05:01:36.007755743 HTTPClient:NFO Connecting to 127.0.0.1:5005
{
"result" : {
"error" : "txnNotFound",
"error_code" : 29,
"error_message" : "Transaction not found.",
"request" : {
"command" : "tx",
"transaction" : "AF24700729D1D68382FCD0506BE902B8562D90056F754210E200BC763DACBAD4"
},
"status" : "error"
}
}
Like OP I can find the transaction via transaction_entry and account_tx methods. It's only the tx method that seems affected here.
here's the server_info as well, in case it's useful
{
"result" : {
"info" : {
"build_version" : "1.3.1",
"complete_ledgers" : "49673891-49688285",
"hostid" : "wallet",
"io_latency_ms" : 1,
"jq_trans_overflow" : "0",
"last_close" : {
"converge_time_s" : 3.019,
"proposers" : 33
},
"load" : {
"job_types" : [
{
"avg_time" : 27,
"job_type" : "untrustedValidation",
"peak_time" : 108
},
{
"job_type" : "ledgerRequest",
"per_second" : 5
},
{
"job_type" : "untrustedProposal",
"peak_time" : 109,
"per_second" : 42
},
{
"avg_time" : 15,
"job_type" : "ledgerData",
"peak_time" : 318,
"per_second" : 2
},
{
"in_progress" : 1,
"job_type" : "clientCommand",
"per_second" : 10
},
{
"job_type" : "transaction",
"peak_time" : 3,
"per_second" : 8
},
{
"job_type" : "batch",
"peak_time" : 21,
"per_second" : 7
},
{
"avg_time" : 14,
"job_type" : "advanceLedger",
"peak_time" : 106,
"per_second" : 4
},
{
"job_type" : "fetchTxnData",
"per_second" : 3
},
{
"job_type" : "trustedValidation",
"peak_time" : 10,
"per_second" : 6
},
{
"job_type" : "writeObjects",
"peak_time" : 11,
"per_second" : 6
},
{
"in_progress" : 1,
"job_type" : "acceptLedger"
},
{
"job_type" : "trustedProposal",
"per_second" : 11
},
{
"avg_time" : 211,
"job_type" : "sweep",
"peak_time" : 843
},
{
"avg_time" : 6,
"job_type" : "heartbeat",
"peak_time" : 21
},
{
"job_type" : "peerCommand",
"per_second" : 1508
},
{
"job_type" : "diskAccess",
"peak_time" : 11,
"per_second" : 6
},
{
"job_type" : "processTransaction",
"peak_time" : 2,
"per_second" : 8
},
{
"job_type" : "SyncReadNode",
"peak_time" : 1,
"per_second" : 55
},
{
"job_type" : "AsyncReadNode",
"per_second" : 1153
},
{
"job_type" : "WriteNode",
"peak_time" : 2,
"per_second" : 255
}
],
"threads" : 6
},
"load_factor" : 1,
"peer_disconnects" : "1",
"peer_disconnects_resources" : "0",
"peers" : 21,
"pubkey_node" : "n94Jw9GEnr2nW72bf7o3HGLfYAVzAS5wbjggjZZTMbHrUnw1CEsP",
"pubkey_validator" : "none",
"server_state" : "full",
"server_state_duration_us" : "9848312560",
"state_accounting" : {
"connected" : {
"duration_us" : "316270770",
"transitions" : 1
},
"disconnected" : {
"duration_us" : "2180958",
"transitions" : 1
},
"full" : {
"duration_us" : "9848312560",
"transitions" : 1
},
"syncing" : {
"duration_us" : "5203864",
"transitions" : 1
},
"tracking" : {
"duration_us" : "0",
"transitions" : 1
}
},
"time" : "2019-Aug-30 05:06:30.200764",
"uptime" : 10171,
"validated_ledger" : {
"age" : 8,
"base_fee_xrp" : 1e-05,
"hash" : "4510878A8D2DCCDAE70330D5E5658F0501A79B527907F26CB9ECAD223E3BC441",
"reserve_base_xrp" : 20,
"reserve_inc_xrp" : 5,
"seq" : 49688285
},
"validation_quorum" : 27,
"validator_list" : {
"count" : 1,
"expiration" : "2019-Oct-29 00:00:00.000000000",
"status" : "active"
}
},
"status" : "success"
}
Fixing #1873 might help here.
My suspicion is that the underlying SQLite database does not have this transaction, whereas the key-value store does. The tx() method queries SQLite, and transaction_entry looks in the key-value store. To confirm this, the following command line will give the list of transactions for that ledger:
sqlite3 path_to_transaction.db "select TransID from Transactions where LedgerSeq = 21474047"
Substitute "path_to_transaction.db" as appropriate for your system--the directory is the [database_path] parameter from rippled.cfg and the database file in that directory is transaction.db.
rippled does not atomically write transactions to both the key-value store and to the SQLite database. It's possible that a process shutdown happened while the ledger was being committed to disk with the key-value store being committed but the SQLite data not.
I agree with @mtravis's suspicion, SQLite did not have the tx stored while the node store did. I believe there are a couple of possibilities as to why that would be. As @mtravis mentioned, the rippled process may have been terminated after the node store save but before SQLite. It is possible to issue tx
and transaction_entry
RPCs at the same time while the ledger is being stored and receive txnNotfound
and a valid reply accordingly. A more probable cause could be that the tx
RPC is received before the containing ledger is stored. On examining the time and results from the tx
, transaction_entry
and server_info
RPCs, that appears to be the case.
Based on @miguelportilla looking at the timestamps involved, I agree that most likely the tx command was issued before the data was written to SQLite but after the ledger was validated.
@miguelportilla @mtrippled If I understand correctly, you guys are suggesting that it only happened because I sent the tx
command too early even before the ledger is stored? I find it hard to believe to be the case though. I only copied/pasted some commands I did into this issue, but I actually tried both tx
and transaction_entry
back and forth, and the tx
gave me the same error even after successful transaction_entry
. Also, the reason I actually found this problem is that I am running software subscribing to new ledgers from rippled
via WebSocket and the tx
command failed on the client-side upon receiving notification for the ledger. How could rippled send out WebSocket notification even before the ledger is successfully persisted?
@miguelportilla @mtrippled I appreciate you taking the time to look into this. I've just added a fallback that validates these problematic transactions against the s1.ripple.com for now. Wish I could be more help.
@mtrippled how confident are you that this is a timing issue? Anything we should do or can we close this?
Closing due to inactivity. If the issue persists, please open a new issue (feel free to link back to this one if relevant).
I am runing rippled
v1.3.1
in a docker container on testnet with base image beingdebian:stretch-slim
, and am experiencing some problem with retrieving transaction2E3E7BE568A35C580CC03B2EAEBB18303DD82C0043D81E2054D20548F0702591
in ledger21474047
.When I use the command
rippled tx
, I got the following errorHowever, when I try
transaction_entry
, it works no problem with the following resultIt seems to me that clearly rippled has that transaction in the db but could not find it unless I instruct it to search in a particular ledger.
My db config is as following
and my
server_info
shows that the ledger is in the range ofcomplete_ledgers