wallet_encryption.py fails on macos

AkioNak commented at 11:13 am on February 7, 2018: contributor

#12101 adds 2 edge cases to wallet_encryption.py, but those cases always fail with my mac.

in the debug.log:

02018-02-07 10:31:10.016784 Received a POST request for / from 127.0.0.1:53758
12018-02-07 10:31:10.016861 ThreadRPCServer method=walletpassphrase
22018-02-07 10:31:10.120324 queue run of timer lockwallet(wallet.dat) in 1073741224 seconds (using HTTP)
32018-02-07 10:31:10.121092 Received a POST request for / from 127.0.0.1:53758
42018-02-07 10:31:10.121184 libevent: kevent: Invalid argument
52018-02-07 10:31:10.121196 ThreadRPCServer method=getwalletinfo
62018-02-07 10:31:10.121208 Exited http event loop

It seems 1073741224 == (1 « 30) - 600 is accepted by libevent.event_add(), but fails libevent.event_base_dispatch() via kevent() and stop http thread loop, therefore following RPC(getwalletinfo) is timed out.

[enviroment] MacBook Pro (macOS 10.13.3/i7 2.2GHz/mem 16GB/SSD) Bitcoin Core version v0.16.99.0-1462bde76 (release build)

[how to reproduce the issue] wallet_encryption.py or bitcoin-cli walletpassphrase “yourpassphrase” 100000002

fanquake added the label Tests on Feb 7, 2018

AkioNak commented at 2:36 am on February 8, 2018: contributor

I think the problem is that invalidness of specified timeout value and/or stopping the http server thread are not prevented and/or not notify to the client. However, to clarify what happens, I made a simple example code that fails event_base_dispatch () below:

2 event_add() both returns 0.
callback() called only once at 1s later.
got [warn] kevent: Invalid argument after callback().
event_base_dispatch() returns -1 instead of 1(no events left).

 0#include <event2/event.h>
 1#include <event2/event_struct.h>
 2
 3static void callback(evutil_socket_t fd, short event, void *arg) {
 4	struct timeval called;
 5	evutil_gettimeofday(&called, NULL);
 6	printf("callback at %d.\n", (int)called.tv_sec);
 7}
 8
 9int main() {
10	struct event_base *base = event_base_new();
11	struct event timeout1, timeout2;
12	event_assign(&timeout1, base, -1, 0, callback, (void*) &timeout1);
13	event_assign(&timeout2, base, -1, 0, callback, (void*) &timeout2);
14
15	struct timeval tv;
16	evutil_timerclear(&tv);
17
18	tv.tv_sec = 100000003;
19	int ret = event_add(&timeout1, &tv);
20	printf("event_add(timeout: %.3f seconds) return: %d.\n", tv.tv_sec + (tv.tv_usec / 1.0e6), ret);
21
22	tv.tv_sec = 1;
23	ret = event_add(&timeout2, &tv);
24	printf("event_add(timeout: %.3f seconds) return: %d.\n", tv.tv_sec + (tv.tv_usec / 1.0e6), ret);
25
26	evutil_gettimeofday(&tv, NULL);
27	printf("start at %d.\n", (int)tv.tv_sec);
28
29	ret = event_base_dispatch(base);
30	printf("event_base_dispatch() return: %d\n", ret);
31
32	return (0);
33}

Sjors commented at 6:00 pm on February 20, 2018: member

I’m seeing the same issue (master @ ffc6e48b ). See logs.

AkioNak commented at 4:43 am on February 21, 2018: contributor

Another code example using the kevent system call directly. This code explain the timer event(EVFILT_TIME) accept large value, and the event monitoring restriction(kevent()’s 6th parameter named timeout) does not accept that value.

I think libevent uses the latter one to implement the timer event. https://github.com/libevent/libevent/blob/master/kqueue.c#L302-L303

NOTE: FreeBSD 11.1 accepts 100000003 by both example.

 0#include <stdio.h>
 1#include <sys/types.h>
 2#include <sys/event.h>
 3#include <sys/time.h>
 4
 5void enqueue(int kq, int ident, int timeout) {
 6	struct kevent e;
 7	EV_SET(&e, ident, EVFILT_TIMER, EV_ADD | EV_ONESHOT, NOTE_SECONDS, timeout, NULL);
 8	kevent(kq, &e, 1, NULL, 0, NULL);
 9}
10
11void dequeue(int kq, int timeout) {
12	struct timespec t;
13	t.tv_sec = timeout;
14	t.tv_nsec = 0;
15
16	struct kevent e;
17	int r = kevent(kq, NULL, 0, &e, 1, &t);
18	if (r == -1) perror("dequeue fail");
19	if (r == 0) printf("event monitor timeout.\n");
20	if (r == 1) printf("dequeue success: ident=%lx.\n", e.ident);
21}
22
23int main()
24{
25	int kq = kqueue();
26	if (kq == -1) return -1;
27
28	enqueue(kq, 9, 100000003);
29	enqueue(kq, 8, 2);
30
31	dequeue(kq, 1);
32	dequeue(kq, 3);
33	dequeue(kq, 100000003);
34
35	return 0;
36}

AkioNak commented at 11:03 am on February 22, 2018: contributor

An idea to get rid of this restriction.

walletpassphrase(): When calling RPCRunLater() , set the last parameter to min(nSleepTime, 100000000) instead of nSleepTime.
LockWallet (): If current time still not have arrived to nRelockTime, call RPCRunLater() again with the last parameter to min(remain time, 100000000).

achow101 commented at 4:03 pm on February 22, 2018: member

So the issue is that 2^30 seconds is still too big for some OSes?

AkioNak commented at 10:10 pm on February 22, 2018: contributor

Yes, I think so.

sdaftuar commented at 3:21 pm on April 6, 2018: member

I can reproduce this as well – tests fail for me on my mac in the same way as for the OP. Can we tag this as a bug please?

MarcoFalke added the label Bug on Apr 6, 2018

MarcoFalke added this to the milestone 0.17.0 on Apr 6, 2018

MarcoFalke closed this on Apr 9, 2018

DrahtBot locked this on Sep 8, 2021

wallet_encryption.py fails on macos #12375