Repository: JoinMarket-Org/joinmarket-clientserver
Issue category: Performance Issue

Issue:
yg-privacyenhanced.py: excessive CPU usage
At first startup of the Yield Generator, CPU usage seems acceptable, but as it sits running for a few days, it starts using excessive amounts of CPU time. It seems to depend on how many CoinJoins it has participated in. Case in point: I have two instances of `yg-privacyenhanced.py` running (with separate JM wallets and separate Bitcoin Core wallets), one running with native SegWit and the other with transitional SegWit. Both were started at the same time, about 154 hours ago. One has used about 25 minutes of CPU time. The other has used about 75 hours of CPU time — i.e., nearly half of the wall-clock time that it has been running!

Attaching to the well-behaved instance with `strace` shows that it is making one `getblockcount` RPC call and one `listtransactions` RPC call about every 4-5 seconds. Not great, but okay. (Polling is evil.) Attaching `strace` to the misbehaving instance shows that it is obsessively (many times per second!) calling `gettransaction`, all for the same transaction ID. The responses from Bitcoin Core show that the specified transaction has over 200 confirmations, so why is JoinMarket obsessively hammering requests for it?

If I restart the `yg-privacyenhanced.py` script, then the new instance is well behaved for a while, but eventually it will start obsessively hammering requests for some particular transaction ID again.


Hints:
>  it is obsessively (many times per second!) calling `gettransaction`, all for the same transaction ID. The responses from Bitcoin Core show that the specified transaction has over 200 confirmations, so why is JoinMarket obsessively hammering requests for it?

It shouldn't, sounds like a bug somewhere.
> RPC call and one listtransactions RPC call about every 4-5 seconds. Not great, but okay. (Polling is evil.)

That's right, there is a single global 5 second polling loop (`WalletService.transaction_monitor`). (If you think this is bad, there used to be a polling loop per transaction we do!).

> Attaching strace to the misbehaving instance shows that it is obsessively (many times per second!) calling gettransaction, all for the same transaction ID.

That's pretty interesting, at least in the sense that I don't off the top of my head have any reason why a Joinmarket script (a yg specifically, would do that).
But in one sense it's a bit unclear - "obsessively many times per second" - but for how long? Continuously without end? Or for like 1-2 seconds? There might be a badly conceived loop somewhere that could result in the latter. I'm thinking, related to PoDLE verification, but I'd need to check. But the former would be really bizarre.

> But in one sense it's a bit unclear - "obsessively many times per second" - but for how long? Continuously without end? Or for like 1-2 seconds?

Continuously without end. That's how my JoinMarket process got up to 75 hours of CPU time used and was still climbing. Presumably it's only *not* using all 100% of a CPU core because it has to wait for responses from Bitcoin Core.
It has happened again. The repeating pattern of syscalls I am seeing is as follows:

1. `sendto` is called with payload:
    ```
    POST /wallet/joinmarket-sw0 HTTP/1.1
    Host: localhost:8332
    Accept-Encoding: identity
    Content-Length: 55
    User-Agent: joinmarket
    Content-Type: application/json
    Accept: application/json
    Authorization: Basic ##redacted##
    
    ```
1. `sendto` is called with payload:
    ```
    {"method": "getblockcount", "params": [], "id": 506225}
    ```
1. `recvfrom` returns payload:
    ```
    HTTP/1.1 200 OK
    Content-Type: application/json
    Date: Mon, 25 Jan 2021 20:11:45 GMT
    Content-Length: 43
    
    {"result":667641,"error":null,"id":506225}
    ```
1. `sendto` is called with payload:
    ```
    POST /wallet/joinmarket-sw0 HTTP/1.1
    Host: localhost:8332
    Accept-Encoding: identity
    Content-Length: 75
    User-Agent: joinmarket
    Content-Type: application/json
    Accept: application/json
    Authorization: Basic ##redacted##
    
    ```
1. `sendto` is called with payload:
    ```
    {"method": "listtransactions", "params": ["*", 100, 0, true], "id": 506226}
    ```
1. `recvfrom` returns payload:
    ```
    HTTP/1.1 200 OK
    Content-Type: application/json
    Date: Mon, 25 Jan 2021 20:11:45 GMT
    Content-Length: 46976
    
    {\"result\":[…##redacted##…
1. `sendto` is called with payload:
    ```
    POST /wallet/joinmarket-sw0 HTTP/1.1
    Host: localhost:8332
    Accept-Encoding: identity
    Content-Length: 128
    User-Agent: joinmarket
    Content-Type: application/json
    Accept: application/json
    Authorization: Basic ##redacted##
    
    ```
1. `sendto` is called with payload:
    ```
    {"method": "gettransaction", "params": ["e##…##c", true], "id": 506227}
    ```
1. `recvfrom` returns payload:
    ```
    HTTP/1.1 200 OK
    Content-Type: application/json
    Date: Mon, 25 Jan 2021 20:11:45 GMT
    Content-Length: 10618
    
    {"result":{"amount":-##redacted##,"fee":##redacted##,"confirmations":0,"trusted":false,"txid":"e##…##c","walletconflicts":[],"time":1611564203,"timereceived":1611564203,"bip125-replaceable":"unknown","details":[…],"hex":…},"error":null,"id":506227}
    ```
1. Previous three steps are repeated 21 times with `"id"` numbers incrementing from 506228 to 506248.
1. `epoll_wait` is called with a timeout of around 2.6 seconds — presumably the remainder of the 5-second polling interval.
1. Restart from step 1.

**TL;DR:** In each iteration of the 5-second polling loop, `yg-privacyenhanced.py` calls `getblockcount`, reads the response, calls `listtransactions`, reads the response, and then calls `gettransaction` with the same TxID 22 times, reading the response after each call.
My other instance of `yg-privacyenhanced.py` is not currently exhibiting the excessive CPU utilization problem, and its polling loop is only calling `getblockcount` and `listtransactions` once every 5 seconds. It is not calling `gettransaction` at all. It has completed a CoinJoin in its current run, so the difference isn't that the bad one has done a CoinJoin while the good one hasn't yet; no, both instances have done CoinJoins in their current runs.
Thanks for this. I will have to take a look at what might be going on, but basically if I read you right, you're saying that `gettransaction` is being called 22 times per polling loop, on one txid - but also, you're saying that's taking around 2.5 seconds, is that right?
I think there is unnecessary use of list in `transaction_monitor` when it should be a set. While there's some accounting for duplication, it seems very likely that there are redundant calls to gettransaction because of it (though the exact circumstances I'd need to look at). I'll spend some time testing it out tomorrow.
> you're saying that `gettransaction` is being called 22 times per polling loop, on one txid - but also, you're saying that's taking around 2.5 seconds, is that right?

Correct on all points. Note that the `listtransactions` call is pretty heavy since it always asks for 100 transactions. Seems like it should only ask for the latest 1 transaction and exponentially fetch further back until it reaches a transaction it already knows about.
I'm not sure that matters, but I could believe it. Iirc listtransactions return is not particularly large as the data it returns is relatively compact but ... in any case i need to spend a bit of time checking.

The part of the story that confuses me though is, why you specifically are getting a large *CPU* usage - I would have thought even if the listtransactions return were large it couldn't/wouldn't cause that. More plausible would be our parsing code converting the gettransaction results into deserialized objects, that could at least feasibly use a lot of CPU.
See the commit notes for #795 ... in testing I saw a 4 times or so reduction in the number of gettx calls for a full tumbler run (counting both maker and taker sides) (but meticulous accounting is tricky).

My initial thought was just caching of gettx results; but across monitoring loop invocations that makes no sense, as the main (but not only) reason we do those calls is to check confirmation status.

I could get a little more into the weeds than I did in that commit comment, but at root, after making sure at least we don't use a stupidly redundant amount of calls, I was always of the opinion that a few extra rpc calls shouldn't matter too much; I still absolutely don't understand why say 20-25 rpc calls would chew such a huge amount of CPU; I've never seen anything similar myself.

But anyway - that patch is worth running (I guess it'll get merged very soon), as it is bound to at least reduce the number of calls in pretty much any usage scenario.
@AdamISZ: Thank you for your work on this. To clarify, it is not the `listtransactions` call that is chewing up CPU time. A properly behaving YG instance (despite polling `listtransactions` every 5 seconds) uses less than 0.1% of my CPU time. It's the misbehaving instance (which calls `gettransaction` multiple times per polling cycle) that uses hours upon hours of CPU time. I currently have one that is misbehaving that has used 39 *hours* of CPU time in the past week or so since it started. My other instance, which was started at the same time, has used only 33 *minutes* of CPU time. Huge difference, obviously.

Oddly, the behaving instance isn't calling `gettransaction` in its polling loop *at all*, while the misbehaving instance is calling `gettransaction` many times. I understand that the number of confirmations changes over time, but do you really still need to be tracking it after 488 confirmations? At some point can't you just be confident that it's never going to unconfirm?

I'll apply the patch from #795 and see what impact it has. Thanks again.
> I understand that the number of confirmations changes over time, but do you really still need to be tracking it after 488 confirmations? At some point can't you just be confident that it's never going to unconfirm?

See my response to @undeath in the related PR #795 - once confirmed, we do not repeatedly call gettransaction for the txid. My reference above to not being able to cache etc. etc. is specifically that we keep doing the call once per loop, as long as it hasn't changed from 0 to 1 confs.

My best guess right now is there's a code path I'm missing, perhaps due to some unusual circumstance (e.g. what about a conflict? do you see anything about that, or anything else unusual, in the log for that bot?), but my last review didn't yet throw something up.
Apart from conflicts, the other edge case I see from the code:

Is it possible for you to get 100+ new entries in your listtransactions output in < 5 seconds?

For context, listtransactions lists by recency, all transactions relevant to your wallet. The nuance is that it can have multiple entries per transaction; e.g. if there is a send from utxo1 and a creation of utxo2, it will list it twice, once for each affected address. So while having 100 entries in 5 seconds is extremely unlikely for a "normal" user, it's not hard to find circumstances where it would happen in complete generality of use-cases.

I felt this was a reasonable trade-off when writing the code, my reasoning being: I don't want stupidly large listtransactions returns as you have to do that in every loop; and while in the extreme it's possible someone could get dangling transactions here, it'd be super-unlikely and they could just restart.
> what about a conflict? do you see anything about that, or anything else unusual, in the log for that bot?

@AdamISZ: I have an instance exhibiting the excessive CPU utilization again right now, and I don't see anything unusual in its log. Your patch has reduced the `gettransaction` calls to one per polling cycle, but the CPU usage is still crazy high. What I'm noticing now is that significant wall-clock time elapses between the call to `recvfrom` that receives the end of the `gettransaction` response and the following call to `epoll_wait`, a time during which the process would be CPU-bound in user-mode code. I am seeing about 1.2 seconds between receiving the `gettransaction` response and beginning the next wait, so something you're doing is very time-inefficient. Could it be your transaction parsing code?

> Is it possible for you to get 100+ new entries in your listtransactions output in < 5 seconds?

No, definitely not. I run each JoinMarket instance on its own dedicated Bitcoin Core wallet, so there's nothing else happening in the wallet, and I am most definitely not getting anywhere close to 100 CoinJoins per 5 seconds. (Closer to 100 CoinJoins per 5 *weeks*.)
From instrumenting the call to `BitcoinCoreInterface.get_deser_from_gettransaction` (which calls the function `stream_deserialize` in python-bitcointx's class `CTransaction` - see [here](https://github.com/Simplexum/python-bitcointx/blob/d945bf764a3f585e2bf075237a78a708bffefde7/bitcointx/core/__init__.py#L1089) i see no more than ~ 5ms per call across a bunch of simple txs on regtest, on my laptop ("i7-7700HQ CPU @ 2.80GHz × 8" so it's fairly beefy, but still ... it's not as if there's parallelisation here).
 
But if I look into this with more variety of transactions, I still see pretty strong evidence that there isn't really a case where the deserialization routine uses significant CPU (and tbh I would definitely not expect it to). My intuition with this case was always that there's something funky going on at the network/rpc/operating system/disk call level, i.e. specific to something about the environment in which it's running. I know your recent analysis (and thanks for doing meticulous analysis again; it's incredibly helpful) leads to you to believe otherwise, but I'd really want to delve into any delta between the cases you've had where you don't see this and those where you do ... I'm increasingly not really believing there's a JM code reason for this.


As to my belief that the deserialization routine doesn't eat CPU, here's an example of what I mean; this is the output of [this](https://github.com/JoinMarket-Org/joinmarket-clientserver/blob/8d122fce2ab7fab965825b0583a05f5ac5c3cf37/scripts/snicker/snicker-finder.py) script with the `-j` flag:

```
2021-02-05 13:28:16,084 [INFO]  Finished processing block: 669116
2021-02-05 13:28:20,017 [INFO]  Found Joinmarket coinjoin transaction: f7e2496e956422e4320838011ec4bec5ea90664dff2db8ef8ac2f89e36017629 in block: 669117
2021-02-05 13:28:20,110 [INFO]  Finished processing block: 669117
2021-02-05 13:28:24,272 [INFO]  Finished processing block: 669118
2021-02-05 13:28:28,408 [INFO]  Finished processing block: 669119
2021-02-05 13:28:33,814 [INFO]  Finished processing block: 669120
2021-02-05 13:28:38,500 [INFO]  Finished processing block: 669121
2021-02-05 13:28:41,656 [INFO]  Found SNICKER transaction: 2e66ffce4c0406415927acfc488f7bc1d996427cc6ba90dad909505a56af5fd1 in block: 669122
2021-02-05 13:28:43,067 [INFO]  Finished processing block: 669122
2021-02-05 13:28:44,294 [INFO]  Found Joinmarket coinjoin transaction: b3044511c67fa4c8752454e0b70b592bbbf8bfaef03cc094a885bf299e647459 in block: 669123
2021-02-05 13:28:47,997 [INFO]  Finished processing block: 669123
2021-02-05 13:28:53,512 [INFO]  Finished processing block: 669124
2021-02-05 13:28:55,391 [INFO]  Found Joinmarket coinjoin transaction: 422e0aec25e667eebb1c453b446b65726440623c69b2ab381681ede2afd7c514 in block: 669125
2021-02-05 13:28:57,964 [INFO]  Finished processing block: 669125
2021-02-05 13:29:03,302 [INFO]  Finished processing block: 669126
2021-02-05 13:29:08,117 [INFO]  Finished processing block: 669127
2021-02-05 13:29:13,056 [INFO]  Finished processing block: 669128
```
4-5 seconds per block appears typical ... Python after all is *not* fast so this isn't too bad really ... and blocks are all "full-ish" in this period; we're definitely dealing with transaction numbers in the thousands, and *every* transaction is deserialized, as well as other things being done (block serialization; pattern matching checks on the individual deserialized txs, basically). Even further, we may need to call `deserialize` more than once per transaction; see the algo used here:

https://github.com/JoinMarket-Org/joinmarket-clientserver/blob/8d122fce2ab7fab965825b0583a05f5ac5c3cf37/jmbitcoin/jmbitcoin/blocks.py#L16-L42

Given that this experiment covers *all* the types of transactions we see, I think it should be reasonably reliable.

Huh, I just had a thought; maybe checkout the SNICKER PR #768 and just run the above script and see how fast it is? (`cd scripts/snicker; python snicker-finder.py -j 669100` (or any other block height to start; just quit it before it finishes if too slow).


> Huh, I just had a thought; maybe checkout the SNICKER PR #768 and just run the above script and see how fast it is?

```
2021-02-06 14:09:36,339 [INFO]  Finished processing block: 669116
2021-02-06 14:09:52,238 [INFO]  Found Joinmarket coinjoin transaction: f7e2496e956422e4320838011ec4bec5ea90664dff2db8ef8ac2f89e36017629 in block: 669117
2021-02-06 14:09:52,533 [INFO]  Finished processing block: 669117
2021-02-06 14:10:09,018 [INFO]  Finished processing block: 669118
2021-02-06 14:10:24,557 [INFO]  Finished processing block: 669119
2021-02-06 14:10:46,027 [INFO]  Finished processing block: 669120
2021-02-06 14:11:04,486 [INFO]  Finished processing block: 669121
2021-02-06 14:11:15,397 [INFO]  Found SNICKER transaction: 2e66ffce4c0406415927acfc488f7bc1d996427cc6ba90dad909505a56af5fd1 in block: 669122
2021-02-06 14:11:21,325 [INFO]  Finished processing block: 669122
2021-02-06 14:11:23,961 [INFO]  Found Joinmarket coinjoin transaction: b3044511c67fa4c8752454e0b70b592bbbf8bfaef03cc094a885bf299e647459 in block: 669123
2021-02-06 14:11:40,018 [INFO]  Finished processing block: 669123
2021-02-06 14:12:01,805 [INFO]  Finished processing block: 669124
2021-02-06 14:12:07,471 [INFO]  Found Joinmarket coinjoin transaction: 422e0aec25e667eebb1c453b446b65726440623c69b2ab381681ede2afd7c514 in block: 669125
2021-02-06 14:12:19,141 [INFO]  Finished processing block: 669125
2021-02-06 14:12:40,288 [INFO]  Finished processing block: 669126
2021-02-06 14:12:59,261 [INFO]  Finished processing block: 669127
2021-02-06 14:13:18,015 [INFO]  Finished processing block: 669128
```

It's certainly slower than it is on your machine, by a factor of about 4, but that's not altogether surprising, given that I'm running on an Intel Core 2 Quad Q6600, a 14-year-old CPU. Still, though, that doesn't explain 1.2 seconds to deserialize a single transaction, so I'm inclined to agree with you that the deserialization is not the CPU hog in my case.

I wish I knew anything about profiling Python code. I'm completely ignorant (by choice) about Python. Is there a Python profiler that can instrument CPU time spent per function call?
I realise I never answered the last Q in this conversation, presumably because I didn't know. While I use pdb for debugging from time to time, I've never even looked for a profiler. This is just what came up from ddg-ing but you can do that as well or better than I: https://docs.python.org/3/library/profile.html

Is this close-able do you think? Apparently we have reduced the overhead but also we're not sure if it's a problem for other users (it isn't for me).
It can be closed for now. I haven't noticed either of my YG instances churning the CPU in a while now. If it happens again, I'll look into profiling and reopen this report.
This is becoming untenable again. I restarted `yg-privacyenhanced.py` 11 hours ago, and just in that time it has used over 4 hours of CPU time. I'll investigate profiling it to see where it's spending all its time.

Patch:
diff --git a/jmclient/jmclient/blockchaininterface.py b/jmclient/jmclient/blockchaininterface.py
index 2402ff7d3..65a4cfcc4 100644
--- a/jmclient/jmclient/blockchaininterface.py
+++ b/jmclient/jmclient/blockchaininterface.py
@@ -292,18 +292,36 @@ def import_addresses_if_needed(self, addresses, wallet_name):
             self.import_addresses(addresses - imported_addresses, wallet_name)
         return import_needed
 
-    def _yield_transactions(self, wallet_name):
-        batch_size = 1000
-        iteration = 0
+    def _yield_transactions(self):
+        """ Generates a lazily fetched sequence of transactions seen in the
+        wallet (under any label/account), yielded in newest-first order. Care
+        is taken to avoid yielding duplicates even when new transactions are
+        actively being added to the wallet while the iteration is ongoing.
+        """
+        num, skip = 1, 0
+        txs = self.list_transactions(num, skip)
+        if not txs:
+            return
+        yielded_tx = txs[0]
+        yield yielded_tx
         while True:
-            new = self._rpc(
-                'listtransactions',
-                ["*", batch_size, iteration * batch_size, True])
-            for tx in new:
-                yield tx
-            if len(new) < batch_size:
+            num *= 2
+            txs = self.list_transactions(num, skip)
+            if not txs:
+                return
+            try:
+                idx = [(tx['txid'], tx['vout'], tx['category']) for tx in txs
+                        ].index((yielded_tx['txid'], yielded_tx['vout'],
+                        yielded_tx['category']))
+            except ValueError:
+                skip += num
+                continue
+            for tx in reversed(txs[:idx]):
+                yielded_tx = tx  # inefficient but more obvious
+                yield yielded_tx
+            if len(txs) < num:
                 return
-            iteration += 1
+            skip += num - 1
 
     def get_deser_from_gettransaction(self, rpcretval):
         """Get full transaction deserialization from a call
@@ -641,7 +659,7 @@ def _get_addr_from_desc(self, desc_str):
         assert desc_str.startswith("addr(")
         return desc_str[5:desc_str.find(")")]
 
-    def _yield_transactions(self, wallet_name):
+    def _yield_transactions(self):
         for u in self.scan_result["unspents"]:
             tx = {"category": "receive", "address":
                 self._get_addr_from_desc(u["desc"])}
diff --git a/jmclient/jmclient/wallet_service.py b/jmclient/jmclient/wallet_service.py
index 332523ed1..0b09d35f5 100644
--- a/jmclient/jmclient/wallet_service.py
+++ b/jmclient/jmclient/wallet_service.py
@@ -1,6 +1,7 @@
 #! /usr/bin/env python
 
 import collections
+import itertools
 import time
 import sys
 from decimal import Decimal
@@ -74,18 +75,19 @@ def __init__(self, wallet):
         # Dicts of registered callbacks, by type
         # and then by txinfo, for events
         # on transactions.
-        self.callbacks = {}
-        self.callbacks["all"] = []
-        self.callbacks["unconfirmed"] = {}
-        self.callbacks["confirmed"] = {}
+        self.callbacks = {
+            "all": [],  # note: list, not dict
+            "unconfirmed": {},
+            "confirmed": {},
+        }
 
         self.restart_callback = None
 
         # transactions we are actively monitoring,
         # i.e. they are not new but we want to track:
-        self.active_txids = []
+        self.active_txs = {}
         # to ensure transactions are only processed once:
-        self.processed_txids = []
+        self.processed_txids = set()
 
         self.set_autofreeze_warning_cb()
 
@@ -200,9 +202,12 @@ def register_callbacks(self, callbacks, txinfo, cb_type="all"):
             # note that in this case, txid is ignored.
             self.callbacks["all"].extend(callbacks)
         elif cb_type in ["unconfirmed", "confirmed"]:
-            if txinfo not in self.callbacks[cb_type]:
-                self.callbacks[cb_type][txinfo] = []
-            self.callbacks[cb_type][txinfo].extend(callbacks)
+            if callbacks:
+                reg = self.callbacks[cb_type].setdefault(txinfo, [])
+                if isinstance(reg, str):
+                    # found a txid breadcrumb for this txinfo
+                    reg = self.callbacks[cb_type].setdefault(reg, [])
+                reg.extend(callbacks)
         else:
             assert False, "Invalid argument: " + cb_type
 
@@ -285,6 +290,23 @@ def check_for_reuse(self, added_utxos):
                 self.autofreeze_warning_cb(utxo)
                 self.disable_utxo(*utxo)
 
+    def _yield_new_transactions(self):
+        """ Constrains the sequence generated by bci._yield_transactions so
+        that it stops just before it would yield the newest transaction
+        previously yielded by _yield_new_transactions.
+        """
+        since_txid = self.last_seen_txid
+        last = True
+        for tx in self.bci._yield_transactions():
+            if 'txid' in tx:
+                txid = tx['txid']
+                if txid == since_txid:
+                    return
+                if last:
+                    self.last_seen_txid = txid
+                    last = False
+            yield tx
+
     def transaction_monitor(self):
         """Keeps track of any changes in the wallet (new transactions).
         Intended to be run as a twisted task.LoopingCall so that this
@@ -294,33 +316,19 @@ def transaction_monitor(self):
         if not self.update_blockheight():
             return
 
-        txlist = self.bci.list_transactions(100)
-        if not txlist:
-            return
-
-        new_txs = []
-        for x in txlist:
-            # process either (a) a completely new tx or
-            # (b) a tx that reached unconf status but we are still
-            # waiting for conf (active_txids)
-            if "txid" not in x:
-                continue
-            if x['txid'] in self.active_txids or x['txid'] not in self.old_txs:
-                new_txs.append(x)
-        # reset for next polling event:
-        self.old_txs = set(x['txid'] for x in txlist if "txid" in x)
         # for this invocation of transaction_monitor, we *don't* want
         # to call `gettransaction` more than once per txid, even if the
         # `listtransactions` result has multiple instances for different
         # wallet labels; so we use a temporary variable to cache.
-        gettx_results = {}
-        for tx in new_txs:
-            txid = tx["txid"]
-            if txid not in gettx_results:
-                res = self.bci.get_transaction(hextobin(txid))
-                gettx_results[txid] = res
-            else:
-                res = gettx_results[txid]
+        seen_txids = set()
+        wallet_name = self.get_wallet_name()
+        for txid in itertools.chain(list(self.active_txs), reversed(
+                [tx['txid'] for tx in self._yield_new_transactions()
+                    if 'txid' in tx])):
+            if txid in seen_txids:
+                continue
+            seen_txids.add(txid)
+            res = self.bci.get_transaction(hextobin(txid))
             if not res:
                 continue
             confs = res["confirmations"]
@@ -330,13 +338,18 @@ def transaction_monitor(self):
             if confs < 0:
                 jlog.info(
                     "Transaction: " + txid + " has a conflict, abandoning.")
+                self.active_txs.pop(txid, None)
                 continue
             if confs == 0:
+                if txid in self.active_txs:
+                    # avoid processing an unconfirmed tx we've already seen
+                    continue
                 height = None
             else:
                 height = self.current_blockheight - confs + 1
 
-            txd = self.bci.get_deser_from_gettransaction(res)
+            txd = self.active_txs.get(txid) or \
+                    self.bci.get_deser_from_gettransaction(res)
             if txd is None:
                 continue
             removed_utxos, added_utxos = self.wallet.process_new_tx(txd, height)
@@ -347,23 +360,31 @@ def transaction_monitor(self):
                 # is absurdly fast, this is considered acceptable compared with
                 # additional complexity.
                 self.log_new_tx(removed_utxos, added_utxos, txid)
-                self.processed_txids.append(txid)
+                self.processed_txids.add(txid)
 
             # first fire 'all' type callbacks, irrespective of if the
             # transaction pertains to anything known (but must
             # have correct label per above); filter on this Joinmarket wallet label,
             # or the external monitoring label:
-            if (self.bci.is_address_labeled(tx, self.get_wallet_name()) or
-                self.bci.is_address_labeled(tx, self.EXTERNAL_WALLET_LABEL)):
+            if (any(self.bci.is_address_labeled(addr, wallet_name) or
+                    self.bci.is_address_labeled(addr,
+                        self.EXTERNAL_WALLET_LABEL)
+                    for addr in res["details"])):
                 for f in self.callbacks["all"]:
                     # note we need no return value as we will never
                     # remove these from the list
                     f(txd, txid)
 
-            # The tuple given as the second possible key for the dict
-            # is such because txid is not always available
-            # at the time of callback registration).
-            possible_keys = [txid, tuple((x.scriptPubKey, x.nValue) for x in txd.vout)]
+            # txid is not always available at the time of callback registration.
+            # Migrate any callbacks registered under the provisional key, and
+            # leave a txid breadcrumb so check_callback_called can find it.
+            txos = tuple((x.scriptPubKey, x.nValue) for x in txd.vout)
+            for cb_type in ["unconfirmed", "confirmed"]:
+                callbacks = self.callbacks[cb_type]
+                reg = callbacks.get(txos)
+                if isinstance(reg, list):
+                    callbacks.setdefault(txid, [])[:0] = reg
+                    callbacks[txos] = txid
 
             # note that len(added_utxos) > 0 is not a sufficient condition for
             # the tx being new, since wallet.add_new_utxos will happily re-add
@@ -373,27 +394,31 @@ def transaction_monitor(self):
             # Note also that it's entirely possible that there are only removals,
             # not additions, to the utxo set, specifically in sweeps to external
             # addresses. In this case, since removal can by definition only
-            # happen once, we must allow entries in self.active_txids through the
+            # happen once, we must allow txids in self.active_txs through the
             # filter.
             if len(added_utxos) > 0 or len(removed_utxos) > 0 \
-               or txid in self.active_txids:
+                    or txid in self.active_txs:
                 if confs == 0:
-                    for k in possible_keys:
-                        if k in self.callbacks["unconfirmed"]:
-                            for f in self.callbacks["unconfirmed"][k]:
-                                # True implies success, implies removal:
-                                if f(txd, txid):
-                                    self.callbacks["unconfirmed"][k].remove(f)
-                                    # keep monitoring for conf > 0:
-                                    self.active_txids.append(txid)
+                    callbacks = [f for f in
+                            self.callbacks["unconfirmed"].pop(txid, [])
+                            if not f(txd, txid)]
+                    if callbacks:
+                        self.callbacks["unconfirmed"][txid] = callbacks
+                    else:
+                        self.callbacks["unconfirmed"].pop(txos, None)
+                    if self.callbacks["confirmed"].get(txid):
+                        # keep monitoring for conf > 0:
+                        self.active_txs[txid] = txd
                 elif confs > 0:
-                    for k in possible_keys:
-                        if k in self.callbacks["confirmed"]:
-                            for f in self.callbacks["confirmed"][k]:
-                                if f(txd, txid, confs):
-                                    self.callbacks["confirmed"][k].remove(f)
-                                    if txid in self.active_txids:
-                                        self.active_txids.remove(txid)
+                    callbacks = [f for f in
+                            self.callbacks["confirmed"].pop(txid, [])
+                            if not f(txd, txid, confs)]
+                    if callbacks:
+                        self.callbacks["confirmed"][txid] = callbacks
+                    else:
+                        self.callbacks["confirmed"].pop(txos, None)
+                        # no more callbacks registered; stop monitoring tx
+                        self.active_txs.pop(txid, None)
 
     def check_callback_called(self, txinfo, callback, cbtype, msg):
         """ Intended to be a deferred Task to be scheduled some
@@ -402,15 +427,27 @@ def check_callback_called(self, txinfo, callback, cbtype, msg):
         If the callback was previously called, return True, otherwise False.
         """
         assert cbtype in ["unconfirmed", "confirmed"]
-        if txinfo in self.callbacks[cbtype]:
-            if callback in self.callbacks[cbtype][txinfo]:
+        callbacks = self.callbacks[cbtype]
+        if isinstance(txinfo, str):
+            txid = txinfo
+            reg = callbacks.get(txid)
+        else:
+            txid = None
+            reg = callbacks.get(txinfo)
+            if isinstance(reg, str):
+                # found a txid breadcrumb for this txinfo
+                txid = reg
+                reg = callbacks.get(txid)
+        if reg:
+            if callback in reg:
                 # the callback was not called, drop it and warn
-                self.callbacks[cbtype][txinfo].remove(callback)
-                # TODO - dangling txids in self.active_txids will
-                # be caused by this, but could also happen for
-                # other reasons; possibly add logic to ensure that
-                # this never occurs, although their presence should
-                # not cause a functional error.
+                reg.remove(callback)
+                if not reg:
+                    del callbacks[txinfo]
+                    if txid:
+                        callbacks.pop(txid, None)
+                        # no more callbacks registered; stop monitoring tx
+                        self.active_txs.pop(txid, None)
                 jlog.info("Timed out: " + msg)
                 return False
             # if callback is not in the list, it was already
@@ -454,8 +491,9 @@ def sync_wallet(self, fast=True):
             self.sync_unspent()
         # Don't attempt updates on transactions that existed
         # before startup
-        self.old_txs = [x['txid'] for x in self.bci.list_transactions(100)
-            if "txid" in x]
+        self.last_seen_txid = next(
+                (tx['txid'] for tx in self.bci._yield_transactions()
+                    if 'txid' in tx), None)
         if isinstance(self.bci, BitcoinCoreNoHistoryInterface):
             self.bci.set_wallet_no_history(self.wallet)
         return self.synced
@@ -668,14 +706,13 @@ def get_all_transactions(self):
         to this wallet, as a list.
         """
         res = []
-        processed_txids = []
-        for r in self.bci._yield_transactions(
-            self.get_wallet_name()):
+        processed_txids = set()
+        for r in self.bci._yield_transactions():
             txid = r["txid"]
             if txid not in processed_txids:
                 tx = self.bci.get_transaction(hextobin(txid))
                 res.append(self.bci.get_deser_from_gettransaction(tx))
-                processed_txids.append(txid)
+                processed_txids.add(txid)
         return res
 
     def get_transaction(self, txid):
@@ -720,7 +757,7 @@ def sync_addresses(self):
         if isinstance(self.wallet, FidelityBondMixin):
             tx_receive = []
             burner_txes = []
-            for tx in self.bci._yield_transactions(wallet_name):
+            for tx in self.bci._yield_transactions():
                 if tx['category'] == 'receive':
                     tx_receive.append(tx)
                 elif tx["category"] == "send":
@@ -743,7 +780,7 @@ def sync_addresses(self):
         else:
             #not fidelity bond wallet, significantly faster sync
             used_addresses_gen = set(tx['address']
-                                  for tx in self.bci._yield_transactions(wallet_name)
+                                  for tx in self.bci._yield_transactions()
                                   if tx['category'] == 'receive')
         # needed for address-reuse check:
         self.used_addresses = used_addresses_gen


Test patch: