Rippled: txnNotFound with command tx but gives back result no problem with command transaction_entry

Created on 1 Aug 2019 · 11Comments · Source: ripple/rippled

I am runing rippled v1.3.1 in a docker container on testnet with base image being debian:stretch-slim, and am experiencing some problem with retrieving transaction 2E3E7BE568A35C580CC03B2EAEBB18303DD82C0043D81E2054D20548F0702591 in ledger 21474047.

When I use the command rippled tx, I got the following error

ripple@xrp:/# rippled tx 2E3E7BE568A35C580CC03B2EAEBB18303DD82C0043D81E2054D20548F0702591 false
Loading: "/etc/opt/ripple/rippled.cfg"
2019-Aug-01 16:09:39.951682040 HTTPClient:WRN Warning: No peer protocol configured
2019-Aug-01 16:09:39.951752305 HTTPClient:NFO Connecting to 127.0.0.1:9091

{
   "result" : {
      "error" : "txnNotFound",
      "error_code" : 29,
      "error_message" : "Transaction not found.",
      "request" : {
         "command" : "tx",
         "transaction" : "2E3E7BE568A35C580CC03B2EAEBB18303DD82C0043D81E2054D20548F0702591"
      },
      "status" : "error"
   }
}

However, when I try transaction_entry, it works no problem with the following result

ripple@xrp:/# rippled transaction_entry 2E3E7BE568A35C580CC03B2EAEBB18303DD82C0043D81E2054D20548F0702591 21474047
Loading: "/etc/opt/ripple/rippled.cfg"
2019-Aug-01 16:09:52.022083860 HTTPClient:WRN Warning: No peer protocol configured
2019-Aug-01 16:09:52.022155579 HTTPClient:NFO Connecting to 127.0.0.1:9091

{
   "result" : {
      "ledger_hash" : "6B1698F0F2D82EB6ECA6AFE0EC19BA3C6CFC1652FD85EF6A70369E0969173546",
      "ledger_index" : 21474047,
      "metadata" : {
         "AffectedNodes" : [
            {
               "ModifiedNode" : {
                  "FinalFields" : {
                     "Account" : "rPLyWcwSzDodry7ou7Bct4cheT9fnf4iSf",
                     "Balance" : "131197034723",
                     "Flags" : 1179648,
                     "OwnerCount" : 1,
                     "Sequence" : 11
                  },
                  "LedgerEntryType" : "AccountRoot",
                  "LedgerIndex" : "0BAF0721503BACDCAC66D0674A090858A402A4AB8605508DA882249C65DF238E",
                  "PreviousFields" : {
                     "Balance" : "131177034723"
                  },
                  "PreviousTxnID" : "EAE52CC32D9B2C7ABC81ADCE36962A8E2389ECA5505C8D7E64650CFBFEA8BAA1",
                  "PreviousTxnLgrSeq" : 21473563
               }
            },
            {
               "ModifiedNode" : {
                  "FinalFields" : {
                     "Account" : "rP5dJGQhrGHtQcnxUxyGHGwVx2KBSHsGcM",
                     "Balance" : "257572371373",
                     "Flags" : 1179648,
                     "OwnerCount" : 5,
                     "Sequence" : 106
                  },
                  "LedgerEntryType" : "AccountRoot",
                  "LedgerIndex" : "9BD52FE0F490B6CE36680205A72A30D6B6C6AE1FD95881E7B7F88792F2465C46",
                  "PreviousFields" : {
                     "Balance" : "257592371418",
                     "Sequence" : 105
                  },
                  "PreviousTxnID" : "6DD1BC3B4EE9C5D631E1A9A51C9A9E370D0CC9D77A078B517A5FFEB0D64AD3AC",
                  "PreviousTxnLgrSeq" : 21473603
               }
            }
         ],
         "TransactionIndex" : 5,
         "TransactionResult" : "tesSUCCESS"
      },
      "status" : "success",
      "tx_json" : {
         "Account" : "rP5dJGQhrGHtQcnxUxyGHGwVx2KBSHsGcM",
         "Amount" : "20000000",
         "Destination" : "rPLyWcwSzDodry7ou7Bct4cheT9fnf4iSf",
         "DestinationTag" : 0,
         "Fee" : "45",
         "Flags" : 2147483648,
         "Sequence" : 105,
         "Signers" : [
            {
               "Signer" : {
                  "Account" : "rwMLQxWvop3Ffqy3u41WgB1xYCQd1MeQK1",
                  "SigningPubKey" : "0314EC974C72CF00306D2110FCF116A42A08B357AEE926D35E1935D4D137FBFD31",
                  "TxnSignature" : "30440220563EC2DF1026B8B720B3BB4AEC786472485BBF235E367576A720B46F91E6B9D502204DA67761BDCE71DFEFE452BD81C505F428F2BCA1CAC3406D87B7CC762061CCD1"
               }
            },
            {
               "Signer" : {
                  "Account" : "rN5QSkwiHaGQiWTZNRDoFLv5gcV94Uqg2n",
                  "SigningPubKey" : "026D21EC6E30BCD2EE66865C45FCF41EF8B2AA73F45C63479BAF3A8E7AF29DA780",
                  "TxnSignature" : "3044022000CA3E37AA31078496C4C26B28DAB664D46FA992FD36C7EA11C8689847EE61E2022051986CDC909BFFBE0AF31164288AF1D8D80DBB61FBBE66182F1E716CBCB89143"
               }
            }
         ],
         "SigningPubKey" : "",
         "TransactionType" : "Payment",
         "hash" : "2E3E7BE568A35C580CC03B2EAEBB18303DD82C0043D81E2054D20548F0702591"
      },
      "validated" : true
   }
}

It 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

[node_db]
type=NuDB
path=/data/db/nudb
online_delete=9000
advisory_delete=0

[ledger_history]
9000

and my server_info shows that the ledger is in the range of complete_ledgers
```ripple@xrp:/# rippled server_info
Loading: "/etc/opt/ripple/rippled.cfg"
2019-Aug-01 16:16:48.005760189 HTTPClient:WRN Warning: No peer protocol configured
2019-Aug-01 16:16:48.005845308 HTTPClient:NFO Connecting to 127.0.0.1:9091

{
"result" : {
"info" : {
"build_version" : "1.3.1",
"complete_ledgers" : "21457007-21474368",
"hostid" : "xrp-0",
"io_latency_ms" : 1,
"jq_trans_overflow" : "0",
"last_close" : {
"converge_time_s" : 3.001,
"proposers" : 6
},
"load" : {
"job_types" : [
{
"job_type" : "untrustedValidation",
"per_second" : 6
},
{
"job_type" : "ledgerData",
"peak_time" : 4
},
{
"in_progress" : 1,
"job_type" : "clientCommand",
"peak_time" : 9,
"per_second" : 6
},
{
"job_type" : "transaction",
"per_second" : 1
},
{
"job_type" : "batch",
"peak_time" : 8,
"per_second" : 1
},
{
"job_type" : "advanceLedger",
"peak_time" : 9,
"per_second" : 1
},
{
"avg_time" : 83,
"job_type" : "fetchTxnData",
"peak_time" : 382,
"per_second" : 2
},
{
"job_type" : "trustedValidation",
"peak_time" : 9
},
{
"job_type" : "writeObjects",
"peak_time" : 2
},
{
"job_type" : "trustedProposal",
"per_second" : 1
},
{
"job_type" : "peerCommand",
"per_second" : 1200
},
{
"job_type" : "diskAccess",
"peak_time" : 2
},
{
"job_type" : "processTransaction",
"per_second" : 1
},
{
"job_type" : "SyncReadNode",
"per_second" : 1
},
{
"job_type" : "AsyncReadNode",
"peak_time" : 1,
"per_second" : 1
},
{
"job_type" : "WriteNode",
"peak_time" : 3,
"per_second" : 16
}
],
"threads" : 6
},
"load_factor" : 1,
"peer_disconnects" : "1",
"peer_disconnects_resources" : "0",
"peers" : 21,
"pubkey_node" : "n9LSUQRGxx22HKCGASWBFDd562h2qKh6BcQb92Xsa5o1PrkKbVRN",
"pubkey_validator" : "none",
"server_state" : "full",
"server_state_duration_us" : "884254164",
"state_accounting" : {
"connected" : {
"duration_us" : "250558408",
"transitions" : 1
},
"disconnected" : {
"duration_us" : "2104131",
"transitions" : 1
},
"full" : {
"duration_us" : "884254164",
"transitions" : 1
},
"syncing" : {
"duration_us" : "63273393",
"transitions" : 1
},
"tracking" : {
"duration_us" : "85",
"transitions" : 1
}
},
"time" : "2019-Aug-01 16:16:48.006650",
"uptime" : 1200,
"validated_ledger" : {
"age" : 6,
"base_fee_xrp" : 1e-05,
"hash" : "D97A15BFED7CDFED3E8CFE7B0251FF764662E51B83FE8D83C031A4D08961C6DE",
"reserve_base_xrp" : 20,
"reserve_inc_xrp" : 5,
"seq" : 21474368
},
"validation_quorum" : 5,
"validator_list" : {
"count" : 1,
"expiration" : "2019-Aug-14 00:00:00.000000000",
"status" : "active"
}
},
"status" : "success"
}
}
```

Bug Low Priority Reviewed

Source

sammy1991106

Most helpful comment

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.

miguelportilla on 5 Sep 2019

👍2

All 11 comments

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.

sammy1991106 on 1 Aug 2019

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 on 1 Aug 2019

@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.

sammy1991106 on 2 Aug 2019

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"
   }

george-of-croton on 4 Sep 2019

Fixing #1873 might help here.

MarkusTeufelberger on 4 Sep 2019

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.

mtrippled on 4 Sep 2019

👍1

miguelportilla on 5 Sep 2019

👍2

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.

mtrippled on 5 Sep 2019

@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?

sammy1991106 on 5 Sep 2019

@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.

george-of-croton on 5 Sep 2019

@mtrippled how confident are you that this is a timing issue? Anything we should do or can we close this?