RPC stuck on walletpassphrase call #18482

issue kryvel openend this issue on March 31, 2020
  1. kryvel commented at 10:53 am on March 31, 2020: none

    Sometimes RPC API stops responding after calling walletpassphrase Unfortunately I can not exactly reproduce this bug. I have tried 20 threads with about 100 requests on each with sequential calling walletpassphrase -> listtransactions -> walletpassphrase -> getransactions, but with no luck.

    Observe it four-five times a day and only restart of node could help.

    It happens not only for bitcoin wallet on mainnet and testnet, but also for litecoin and bitcoin abc wallets, also for mainnet and testnet

    I could provide additional data such as logs, etc.

    System information

    Bitcoin Core version v0.19.1 Litecoin Core Daemon version v0.17.1 Bitcoin ABC Daemon version v0.19.9.0-2f1adeefb

    OS: Debian 10, Xen guest, SSD

    debug.log with last call. after that RPC won’t response anymore.

     02020-03-31T10:17:47Z received: inv (37 bytes) peer=11
 12020-03-31T10:17:47Z got inv: tx bc6099be609e8a81e11b1ba53badd401a3361fe70c8a90dd92cc743ab972b32c  new peer=11
 22020-03-31T10:17:47Z Requesting witness-tx bc6099be609e8a81e11b1ba53badd401a3361fe70c8a90dd92cc743ab972b32c peer=11
 32020-03-31T10:17:47Z sending getdata (37 bytes) peer=11
 42020-03-31T10:17:48Z received: tx (247 bytes) peer=11
 52020-03-31T10:17:48Z AcceptToMemoryPool: peer=11: accepted bc6099be609e8a81e11b1ba53badd401a3361fe70c8a90dd92cc743ab972b32c (poolsz 10 txn, 13 kB)
 62020-03-31T10:17:48Z sending inv (37 bytes) peer=5
 72020-03-31T10:17:48Z received: inv (37 bytes) peer=6
 82020-03-31T10:17:48Z got inv: tx bc6099be609e8a81e11b1ba53badd401a3361fe70c8a90dd92cc743ab972b32c  have peer=6
 92020-03-31T10:17:48Z sending inv (37 bytes) peer=14
102020-03-31T10:17:48Z sending inv (37 bytes) peer=13
112020-03-31T10:17:49Z received: inv (37 bytes) peer=15
122020-03-31T10:17:49Z got inv: tx bc6099be609e8a81e11b1ba53badd401a3361fe70c8a90dd92cc743ab972b32c  have peer=15
132020-03-31T10:17:50Z received: inv (37 bytes) peer=21
142020-03-31T10:17:50Z got inv: tx bc6099be609e8a81e11b1ba53badd401a3361fe70c8a90dd92cc743ab972b32c  have peer=21
152020-03-31T10:17:50Z received: inv (37 bytes) peer=2
162020-03-31T10:17:50Z got inv: tx bc6099be609e8a81e11b1ba53badd401a3361fe70c8a90dd92cc743ab972b32c  have peer=2
172020-03-31T10:17:50Z libevent: epoll_dispatch: epoll_wait reports 1
182020-03-31T10:17:50Z libevent: event_active: 0x561e681d9d08 (fd 9), res 2, callback 0x7fe4fc82e1b0
192020-03-31T10:17:50Z libevent: event_process_active: event: 0x561e681d9d08, EV_READ   call 0x7fe4fc82e1b0
202020-03-31T10:17:50Z libevent: evhttp_get_request_connection: new request from 10.10.1.10:22443 on 52
21
222020-03-31T10:17:50Z libevent: Attempting connection to 10.1.1.10:22443
23
242020-03-31T10:17:50Z libevent: event_add: event: 0x7fe4e0000b60 (fd -1), EV_READ    call 0x7fe4fc81ff40
252020-03-31T10:17:50Z libevent: event_del: 0x7fe4e0000be0 (fd -1), callback 0x7fe4fc81fb40
262020-03-31T10:17:50Z libevent: event_del: 0x7fe4e0000b60 (fd -1), callback 0x7fe4fc81ff40
272020-03-31T10:17:50Z libevent: event_del: 0x7fe4e0000be0 (fd -1), callback 0x7fe4fc81fb40
282020-03-31T10:17:50Z libevent: event_add: event: 0x7fe4e0000b60 (fd 52), EV_READ    call 0x7fe4fc81ff40
292020-03-31T10:17:50Z libevent: Epoll ADD(1) on fd 52 okay. Old events were 0; read change was 1 (add); write change was 0 (none); close change was 0 (none)
302020-03-31T10:17:50Z libevent: event_add: event: 0x7fe4e0000b60 (fd 52), EV_READ   EV_TIMEOUT call 0x7fe4fc81ff40
312020-03-31T10:17:50Z libevent: event_add: event 0x7fe4e0000b60, timeout in 30 seconds 0 useconds, call 0x7fe4fc81ff40
322020-03-31T10:17:50Z libevent: event_del: 0x7fe4e0000be0 (fd 52), callback 0x7fe4fc81fb40
332020-03-31T10:17:50Z libevent: event_add: event: 0x7fe4e0000b60 (fd 52), EV_READ   EV_TIMEOUT call 0x7fe4fc81ff40
342020-03-31T10:17:50Z libevent: event_add: event 0x7fe4e0000b60, timeout in 30 seconds 0 useconds, call 0x7fe4fc81ff40
352020-03-31T10:17:50Z libevent: timeout_next: event: 0x7fe4bc001f90, in 0 seconds, 4053 useconds
362020-03-31T10:17:50Z libevent: epoll_dispatch: epoll_wait reports 1
372020-03-31T10:17:50Z libevent: event_active: 0x7fe4e0000b60 (fd 52), res 2, callback 0x7fe4fc81ff40
382020-03-31T10:17:50Z libevent: event_process_active: event: 0x7fe4e0000b60, EV_READ   call 0x7fe4fc81ff40
392020-03-31T10:17:50Z libevent: event_add: event: 0x7fe4e0000b60 (fd 52), EV_READ   EV_TIMEOUT call 0x7fe4fc81ff40
402020-03-31T10:17:50Z libevent: event_add: event 0x7fe4e0000b60, timeout in 8206112 seconds 564133 useconds, call 0x7fe4fc81ff40
412020-03-31T10:17:50Z libevent: evhttp_add_header: key: Host val: 10.1.1.5:50000
422020-03-31T10:17:50Z libevent: evhttp_add_header: key: Authorization val: Basic c210L.....dFZnMGE3YVk3MnRGcU9qTzhRVT0=
43
442020-03-31T10:17:50Z libevent: evhttp_add_header: key: Accept val: */*
45
462020-03-31T10:17:50Z libevent: evhttp_add_header: key: Content-type val: application/json
47
482020-03-31T10:17:50Z libevent: evhttp_add_header: key: Content-Length val: 111
49
502020-03-31T10:17:50Z libevent: evhttp_read_header: checking for post data on 52
51
522020-03-31T10:17:50Z libevent: evhttp_get_body_length: bytes to read: 111 (in buffer 111)
53
542020-03-31T10:17:50Z libevent: event_del: 0x7fe4e0000b60 (fd 52), callback 0x7fe4fc81ff40
552020-03-31T10:17:50Z libevent: Epoll DEL(1) on fd 52 okay. Old events were 2; read change was 2 (del); write change was 0 (none); close change was 0 (none)
562020-03-31T10:17:50Z libevent: event_del: 0x7fe4e0000b60 (fd 52), callback 0x7fe4fc81ff40
572020-03-31T10:17:50Z Received a POST request for /wallet/test from 10.1.1.10:22443
582020-03-31T10:17:50Z libevent: timeout_next: event: 0x7fe4bc001f90, in 0 seconds, 4053 useconds
592020-03-31T10:17:50Z ThreadRPCServer method=walletpassphrase user=test
602020-03-31T10:17:50Z libevent: epoll_dispatch: epoll_wait reports 0
612020-03-31T10:17:50Z libevent: timeout_next: event: 0x7fe4bc001f90, in 0 seconds, 4053 useconds
622020-03-31T10:17:50Z libevent: epoll_dispatch: epoll_wait reports 0
632020-03-31T10:17:50Z libevent: event_del: 0x7fe4bc001f90 (fd -1), callback 0x561e66258dd0
642020-03-31T10:17:50Z libevent: timeout_process: event: 0x7fe4bc001f90, call 0x561e66258dd0
652020-03-31T10:17:50Z libevent: event_active: 0x7fe4bc001f90 (fd -1), res 1, callback 0x561e66258dd0
662020-03-31T10:17:50Z libevent: event_del: 0x7fe4bc001f90 (fd -1), callback 0x561e66258dd0
672020-03-31T10:17:50Z libevent: event_process_active: event: 0x7fe4bc001f90,    call 0x561e66258dd0
682020-03-31T10:17:50Z libevent: event_del: 0x7fe4bc001f90 (fd -1), callback 0x561e66258dd0
692020-03-31T10:17:58Z received: ping (8 bytes) peer=109
702020-03-31T10:17:58Z sending pong (8 bytes) peer=109
712020-03-31T10:19:13Z Making feeler connection to [2607:fea8:8460:2b4a::4]:18333
722020-03-31T10:19:13Z trying connection [2607:fea8:8460:2b4a::4]:18333 lastseen=842.8hrs
732020-03-31T10:19:18Z connection to [2607:fea8:8460:2b4a::4]:18333 timeout
742020-03-31T10:20:03Z socket closed
752020-03-31T10:20:03Z disconnecting peer=110
762020-03-31T10:21:10Z Making feeler connection to 54.162.24.231:18333
772020-03-31T10:21:10Z trying connection 54.162.24.231:18333 lastseen=556.7hrs
782020-03-31T10:21:15Z connection to 54.162.24.231:18333 timeout
792020-03-31T10:21:16Z Making feeler connection to 70.24.60.7:18333
802020-03-31T10:21:16Z trying connection 70.24.60.7:18333 lastseen=634.4hrs
812020-03-31T10:21:21Z connection to 70.24.60.7:18333 timeout
822020-03-31T10:21:35Z socket closed
832020-03-31T10:21:35Z disconnecting peer=111
  2. kryvel added the label Bug on Mar 31, 2020
  3. promag commented at 11:33 am on March 31, 2020: member

    Do you think you might have overlapping walletpassphrase on the same wallet?

    Also note that doing

    0$ cli walletpassphrase xxx  10
1$ cli walletpassphrase xxx  2

    will make the wallet lock again after 2 seconds.

    debug.log with last call. after that RPC won’t response anymore.

    you mean any RPC?

  4. kryvel commented at 12:08 pm on March 31, 2020: none

    Do you think you might have overlapping walletpassphrase on the same wallet?

    Yes, some walletpassphrase requests are overlapping. But all of them has 15s timeout $ cli walletpassphrase xxx 15s And after that request I’m doing some other, like sendtransaction or listtransactions or some else.

    Also note that doing

    0$ cli walletpassphrase xxx  10
1$ cli walletpassphrase xxx  2

    will make the wallet lock again after 2 seconds.

    Yes, I’m aware of that

    you mean any RPC?

    Yes, any rpc calls.

    And I think node is totally stuck and even doesn’t get new blocks. Also there are no new records in log when trying to make RPC calls. It just timed out on client.

    This is remaining part of log, I have posted above

     02020-03-31T10:22:45Z Making feeler connection to 35.194.22.84:18333
 12020-03-31T10:22:45Z trying connection 35.194.22.84:18333 lastseen=4956.1hrs
 22020-03-31T10:22:50Z connection to 35.194.22.84:18333 timeout
 32020-03-31T10:22:58Z socket closed
 42020-03-31T10:22:58Z disconnecting peer=109
 52020-03-31T10:25:42Z Making feeler connection to [2601:640:106:324c:f1:653f:6988:86c5]:18333
 62020-03-31T10:25:42Z trying connection [2601:640:106:324c:f1:653f:6988:86c5]:18333 lastseen=348.1hrs
 72020-03-31T10:25:47Z connection to [2601:640:106:324c:f1:653f:6988:86c5]:18333 timeout
 82020-03-31T10:26:08Z Making feeler connection to 185.244.215.148:18333
 92020-03-31T10:26:08Z trying connection 185.244.215.148:18333 lastseen=627.5hrs
102020-03-31T10:26:13Z connection to 185.244.215.148:18333 timeout
112020-03-31T10:26:15Z Making feeler connection to 69.10.61.175:18333
122020-03-31T10:26:15Z trying connection 69.10.61.175:18333 lastseen=20.1hrs
132020-03-31T10:26:20Z connection to 69.10.61.175:18333 timeout
142020-03-31T10:26:43Z Making feeler connection to [2003:ea:9f0b:3200:1180:6df2:ba35:efd]:18333
152020-03-31T10:26:43Z trying connection [2003:ea:9f0b:3200:1180:6df2:ba35:efd]:18333 lastseen=4390.7hrs
162020-03-31T10:26:48Z connection to [2003:ea:9f0b:3200:1180:6df2:ba35:efd]:18333 timeout
172020-03-31T10:28:10Z Making feeler connection to 78.47.134.187:18333
182020-03-31T10:28:10Z trying connection 78.47.134.187:18333 lastseen=2949.6hrs
192020-03-31T10:28:10Z connect() to 78.47.134.187:18333 failed after select(): Connection refused (111)
202020-03-31T10:28:38Z Making feeler connection to 188.143.64.147:18333
212020-03-31T10:28:38Z trying connection 188.143.64.147:18333 lastseen=769.8hrs
222020-03-31T10:28:43Z connection to 188.143.64.147:18333 timeout
232020-03-31T10:28:44Z Added connection peer=112
242020-03-31T10:33:32Z Making feeler connection to 51.37.136.38:18333
252020-03-31T10:33:32Z trying connection 51.37.136.38:18333 lastseen=636.5hrs
262020-03-31T10:33:37Z connection to 51.37.136.38:18333 timeout
272020-03-31T10:33:55Z Making feeler connection to [2a01:4f8:150:3096::2]:18333
282020-03-31T10:33:55Z trying connection [2a01:4f8:150:3096::2]:18333 lastseen=172.9hrs
292020-03-31T10:33:55Z Added connection peer=113
302020-03-31T10:42:14Z libevent: epoll_dispatch: epoll_wait reports 0
312020-03-31T10:42:14Z libevent: timeout_next: event: 0x7fe490000f90, in 6350 seconds, 662739 useconds
322020-03-31T11:17:14Z libevent: epoll_dispatch: epoll_wait reports 0
332020-03-31T11:17:14Z libevent: timeout_next: event: 0x7fe490000f90, in 4250 seconds, 561258 useconds
342020-03-31T11:52:14Z libevent: epoll_dispatch: epoll_wait reports 0
352020-03-31T11:52:14Z libevent: timeout_next: event: 0x7fe490000f90, in 2150 seconds, 495487 useconds
  5. promag commented at 12:13 pm on March 31, 2020: member
    I’ll submit a possible fix, I’ll let you know then so you can test it.
  6. promag commented at 1:41 pm on March 31, 2020: member
    @kryvel btw, is this using the same wallet or different wallets?
  7. kryvel commented at 1:50 pm on March 31, 2020: none
    @promag Yes, Node has multiple wallets, which are used in rpc calls
  8. promag commented at 2:02 pm on March 31, 2020: member
    @kryvel how many different wallets?
  9. kryvel commented at 2:16 pm on March 31, 2020: none
    @promag Five wallets but actively used only three of them
  10. kryvel commented at 6:31 pm on March 31, 2020: none
    @promag Also thanks for the very quick reply :) Could you briefly describe the cause of this error?
  11. promag commented at 6:40 pm on March 31, 2020: member
    @kryvel not sure but I’d say its’ related to some concurrency issue and the libevent timer that is triggered to lock the wallet.
  12. kryvel commented at 6:46 pm on March 31, 2020: none

    @promag Is there any workaround? Or it could be fixed only by patch?

    We are forced to stop our services due to this issue..

  13. promag commented at 6:56 pm on March 31, 2020: member

    Only workaround I can think of is to raise the timeout and see if it happens less frequently.

    And I think node is totally stuck and even doesn’t get new blocks.

    It would be nice to know this - could be a deadlock.

  14. kryvel commented at 7:17 pm on March 31, 2020: none

    @promag according the log file, I have posted here #18482 (comment) , there are no entries about new imported blocks after more than hour after stuck happened (this is testnet node)

    I tried to send hundreds of requests (sequential and parallel) but with no luck, node works just fine)

    Maybe you have an idea of some stress test I could run?

  15. kryvel commented at 8:22 pm on March 31, 2020: none
    Maybe this could be related to this issue #14995 ?
  16. promag commented at 11:33 pm on March 31, 2020: member
    @kryvel let me know if #18487 prevents the deadlock.
  17. kryvel commented at 11:44 pm on March 31, 2020: none
    @promag Thank you! I’m going to build and test the fix Let you know asap
  18. promag commented at 10:27 am on April 1, 2020: member
    @kryvel fix got 0.20 tag so feedback is really appreciated asap.
  19. kryvel commented at 11:02 am on April 1, 2020: none

    @promag I’m still testing. Since 2020-04-01 00:41:34 UTC it running without any stucks or deadlocks. But there is also litecoin that running without deadlocks too (it has the same issue). Only bitcoin-abc catch deadlock two times today. So I would like to test it a bit more, to be sure that issue is gone. I will let you know in any case

    Some stats: Currently there is about 30 req/s with

    0rpcthreads=8
1rpcworkqueue=32

    Also if there is any test case for this, I could run it. Or maybe even an idea how to test it properly?

  20. kryvel commented at 0:07 am on April 2, 2020: none

    @promag Finally I could confirm that with your fix deadlock is gone. Thank you!

    Sample script to reproduce issue without fix.

    0for i in {1..100}; do
1    curl  --user user:pass \
2        --data-binary '{"jsonrpc": "1.0", "id":"'$(($(date +%s%N)/1000))'", "method": "walletpassphrase", "params": ["wallet-pass=",1] }' -H 'content-type: text/plain;' \
3        --limit-rate 10K \
4        http://node:8888/wallet/name
5    sleep 1
6done
  21. promag commented at 1:29 am on April 2, 2020: member
    Ok.
  22. MarcoFalke commented at 3:18 pm on April 2, 2020: member
    Thanks for the steps to reproduce. Added a test: #18507
  23. laanwj closed this on Apr 6, 2020
  24. sidhujag referenced this in commit 82255a05ec on Apr 8, 2020
  25. DrahtBot locked this on Feb 15, 2022


kryvel promag MarcoFalke

Labels
Bug

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-10-05 01:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me