IO error reported on "fetch-offers" #375
Comments
|
Further to this, I've tried maybe 15 times now over about 15 minutes and get the same error repeated, when trying the I guess if there's an actionable item here it might be to give the users a more informative error for this one, if, as I suspect, this is about flaky Tor connections. I don't think it's anything else because of the situation I recorded above, where it worked 3rd try. |
|
Thank you sir for trying the app and taking a look. Your work on coinswap before has been foundational for us to start this project. Can you please you share the taker log file? It should be in
Yes, I agree. The software is in early beta, and we have many errors we need to cover manually for more helpful messaging. The error seems to indicate some kind of i/o problem with files, not necessarily tor-related or fatal, although should not happen in regular ubuntu systems. Looking at the log file will give more clarity. We will have much more polish the logs and user interface in the coming releases. |
|
As a swap takes quite some time (2 confs for now) it's also intended to look into the log file. Thus the message to We will do a better job at displaying logs in future. |
|
Thanks. I will post a log in a minute. I noticed something interesting though, while reviewing it myself: I don't think you require txindex for fidelity bond verification, no? Just access the utxo and have the maker provide the information to reconstruct the scriptPubKey? I think that's right, but it's a been a while and I might have forgotten something. |
You are probably right. Although many of our current sync logic requires -txindex. We can potentially do that without it also, but that's planned for later. We will modify the sync code a lot later, by adding more syncing backends, like 3rd party APIs, compact block filters, block streaming via zmq, etc. So the current sync code is not very polished. This seems to be happening because the taker is trying to assert that the fidelity utxo exists, and that call right now requires a -txindex. |
|
OK, currently I have the following situation: whenever I run I notice "shutting down taker" immediately after "completed wallet sync". Hypothesis: is it possible that because each of the 2 makers were reported "bad" as per above, that it concludes there are no available makers, from the offer book, and gives up? This would make sense because yesterday, when trying to (as per the first message, this was the successful attempt after three/two previous attempts failed to bootstrap tor all the way) |
Ah I see. So I'll resync testnet4 with txindex enabled. Did I miss that requirement in the setup instructions? Probably I did? |
|
Is there a way I can change the log level from INFO to DEBUG or similar? Now even after enabling the txindex, I'm still just always getting that "start up, shut down" pattern I showed in the logs above. |
|
OK I found the issue: Line 37 in 84862cf This assumes you are running from the repo root directory. |
We have a bitcoind reference conf file here that tells what flags are needed. https://github.com/citadel-tech/coinswap/blob/master/docs/app%20demos/bitcoind.md#2-setting-up-a-bitcoinconf-file But yes these requirements can be made more clear in the readme instructions too.
Ah this is a hack we had to use to get libtor working with the apps. Thats probably where the Just from your local repo running the app with Also if you get a Pasisng a |
|
Yes, I should have added, it's running fine after moving to the repo root.
OK good to know. |
|
Great. Did the swap complete? it should print a |
|
Seems not, though I'm not sure in detail: obviously that will be ongoing for a while |
|
Huh. That's a recovery being triggered. Did the funding transaction took more than 30 mins to confirm? I will look into the maker logs to see what went wrong. Ya this will take some time, and once recovered you will see the coins again with If possible if you can share the whole log from the start of the coinswap that will be helpful. Every swap has a unique id printed at the start of the log, that will help us identify this particular swap in the makers. |
|
attached is the log up till now. |
|
It's safe to |
|
Yes, it's finished. Please feel free to close this whenever, of course, but I'd appreciate it if you drop a note in here if/when you figure out why it failed; I'm curious to know. |
|
It seemed like everything was normally going. Then the 2nd funding tx took more than 30 mins to confirm. This doesn't usually happen, but can happen in testnet due to unpredictable block issuance. We will release a patch to increase this timeout by more than 30 minutes. In the meantime, can you try the swap again? Most of the time blocks come within 30 minutes, so this was an unfortunate event. |
Are you sure? In my log I see 2 funding/transactions waiting for confirmation before the "Error" part near the end. The first is about 13 minutes, the second is 20 minutes. Is it perhaps the fact that both together are more than 30? Or maybe just connection issues? Oh well, either way, no problem just trying it again. Will do. |
|
It could have been a connection issue but in this case seems like not. The maker log shows that it didn't receive any communication from taker, while the taker seems to be waiting for confirmation. Also, connection errors would have created some more logs and taker would tried more aggressively to reconnect. We are working on a patch to decouple this confirmation wait time from the actual connection dropping wait. And also adding logging in taker to more clearly show how long it is waiting for confirmation. If the plan goes well then we should be able to wait as long as it needs for confirmation without timing out at the maker. Keeping this issue open till this is fixed and will update here. |
|
Here is a log of my second try. The coinswap was successful but just in case it's of interest: |
|
Awesome. Yes thats a succeful swap. Please let us know if any major gaps or potential improvements you can see in the protocol. We also have implemented our own fidelity bond concept here, which is slightly different from joinmarket's fidelity. Would love to hear your feedback on that too. Thanks for trying out and the feedbacks. We will keep continuously improving the systems. |
|
Rather embarrassingly, I realise I didn't actually check whether the coinswap had worked, and now I look, I seem to be missing funds. I've probably just missed a step. Before I started the swap, my balance was 201953 SAT as reported by I could investigate more but running out of time, and I'm sure you can diagnose this way quicker. |
|
Thats weird and it should not happen. There is no extra step to do if the swap completes. We currently have a calculation problem at But in any case it should not be missing any funds and its working as expected in our manual tests. An example: The difference is 1200 sats. This is distributed as Even with the current bug at Can you check It also might happen that taker missed a sync call in last run and the new addresses to watch for was not imported in bitcoin core. Running a You can also check at If the balance is still discrepant, please wait for the above PR merge and try again. |
|
OK, indeed 2025-01-16T09:39:27.805503019-06:00 INFO coinswap::taker::api - Initializing wallet sync I didn't quit the "coinswap" command early, I waited for it to finish, and the command line showed "successfully completed coinswap!!": so it seems something is definitely wrong. |
|
Ah I see, it actually hit recovery routine and the swap didn't complete. And because the recovery was triggered within the swap process itself so the swap process returned as normal printing that line The recovery routine would have sent the timelock tx after the contract tx gets confirmed. But probably that didn't happen for some reason. You can search for Next time when you ran We should bifurcate the log of these two outcomes well. Noting down in our todo. |
I gave the whole log of the |
|
Yeah thats true. No sign of failed swap in the log. Then maybe it was the swap before that which went to recovery? What do you see when you do |
|
|
|
Thats very weird. Is |
|
No: |
|
Okay so thats a contract that is still floating around. Once its matured it can be claimed back with But it still doesn't match with the log. Its clearly showing privkeys have been handed over, but no swap-utxos. Problem is I cannot reproduce this as its not happening in my local or in the live network, or in our functional tests. I will keep trying more swaps and see if I hit a situation like this. There is no obvious error trails in the log to debug also. I can see some transient connection errors but they should be fine. I will keep you posted if I find the root cause. In the mean time, if you fancy, you can try a swap with #380 PR head. We have already updated the live makers with the patches. The PR head will give you latest taker where swap won't fail due to network, or blockchain latency or any transient errors, with some extra helpful logs. We will merge it soon. |
|
Update: we have been able to hone in on the root cause. It's probably happening due to a bug in our recovery code that falsely identifies completed swap utxos as unfinished and attempting to recover from it. This is not observable directly, but after the timelock is spent the incoming swap utxo from the taker would disappear. We are working on a fix and checking if there are more underlying bugs. |
|
First attempt today: everything's set up right but I couldn't access the offers; tor onion services being their usual reliable selves! end of log looks like: |
|
Our makers were temporarily down. All systems up now. Can you try again? |
|
Sorry for delay. Here is my report. I ran this about 15 hours ago but just got back to my terminal to look at it. Running Log file: I now have: which I presume is still wrong? I'm even more confused though by reading the output of list-utxo; it seems to add up to more than 220K! then running list-utxo-contract I get: so my best guess is we have a similar issue to last time? Note the commit I'm running on is current master. So I tried After that, the balance is where we expect. Afaict from looking at the transaction, there is nothing "wrong" here, it's just the second leg of the coinswap right? So maybe there is still some bug that has the taker shut down early? Well either way, hope that helps. (Btw are you interested in migrating to taproot at some point? The 2 of 2 multisig anon set is a bit limited I guess.) |
|
The log says the the swap went smoothly. This is the typical log that signals succesful settlement. The recovery you observed could be a recovery due to the previous bug. The maker's were broadcasting contracts out, so there was a contract that taker identified. The confirmation on the contract tx is 2010 blocks, so the contract was broadcasted long ago and definitely from a previous swap. This bug is fixed, so no more contracts should be seen here on, unless the swap fails. Check the balance, swap balance, and contract balance. You should see only one swap coin in balance and utxo list, as the previous bug made thge makers claim back all swaps after an unknown amount of time. We are working on making the utxos lists more clean, that will be helpful in identifying different types of utxos. If you make more swaps, balance, utxo list and swap process will be as per expected from now on. Thank you so much for testing and reporting, this helped us a lot to streamline the flow.
ETA v0.1.2. We will be using Taproot+Musig2 and compress the funding and contract tx together. That will change the current protocol a lot, but we are definitely going down that road. |
Ah yes, I see. Looks good then 👍
Yeah, makes sense. Thanks for your efforts! |
Running 84862cf on ubuntu 22.04
When running
I get, the first couple of times I try:
I'm guessing (seems it must be) simply an initial failure to connect over Tor to the directory server in the
config.toml. The third time I tried I got anOfferBookstruct returned.The text was updated successfully, but these errors were encountered: