wallet_encryption.py fails on macos #12375

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

   wallet_encryption.log debug.log

   in the debug.log:

   2018-02-07 10:31:10.016784 Received a POST request for / from 127.0.0.1:53758
   2018-02-07 10:31:10.016861 ThreadRPCServer method=walletpassphrase
   2018-02-07 10:31:10.120324 queue run of timer lockwallet(wallet.dat) in 1073741224 seconds (using HTTP)
   2018-02-07 10:31:10.121092 Received a POST request for / from 127.0.0.1:53758
   2018-02-07 10:31:10.121184 libevent: kevent: Invalid argument
   2018-02-07 10:31:10.121196 ThreadRPCServer method=getwalletinfo
   2018-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

2. fanquake added the label Tests on Feb 7, 2018
3. 
   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).

   #include <event2/event.h>
   #include <event2/event_struct.h>
   
   static void callback(evutil_socket_t fd, short event, void *arg) {
   	struct timeval called;
   	evutil_gettimeofday(&called, NULL);
   	printf("callback at %d.\n", (int)called.tv_sec);
   }
   
   int main() {
   	struct event_base *base = event_base_new();
   	struct event timeout1, timeout2;
   	event_assign(&timeout1, base, -1, 0, callback, (void*) &timeout1);
   	event_assign(&timeout2, base, -1, 0, callback, (void*) &timeout2);
   
   	struct timeval tv;
   	evutil_timerclear(&tv);
   
   	tv.tv_sec = 100000003;
   	int ret = event_add(&timeout1, &tv);
   	printf("event_add(timeout: %.3f seconds) return: %d.\n", tv.tv_sec + (tv.tv_usec / 1.0e6), ret);
   
   	tv.tv_sec = 1;
   	ret = event_add(&timeout2, &tv);
   	printf("event_add(timeout: %.3f seconds) return: %d.\n", tv.tv_sec + (tv.tv_usec / 1.0e6), ret);
   
   	evutil_gettimeofday(&tv, NULL);
   	printf("start at %d.\n", (int)tv.tv_sec);
   
   	ret = event_base_dispatch(base);
   	printf("event_base_dispatch() return: %d\n", ret);
   
   	return (0);
   }
   

4. Sjors cross-referenced this on Feb 20, 2018 from issue [WIP] Better stderr testing in functional tests by jnewbery
5. 
   Sjors commented at 6:00 PM on February 20, 2018: member

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

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

   #include <stdio.h>
   #include <sys/types.h>
   #include <sys/event.h>
   #include <sys/time.h>
   
   void enqueue(int kq, int ident, int timeout) {
   	struct kevent e;
   	EV_SET(&e, ident, EVFILT_TIMER, EV_ADD | EV_ONESHOT, NOTE_SECONDS, timeout, NULL);
   	kevent(kq, &e, 1, NULL, 0, NULL);
   }
   
   void dequeue(int kq, int timeout) {
   	struct timespec t;
   	t.tv_sec = timeout;
   	t.tv_nsec = 0;
   
   	struct kevent e;
   	int r = kevent(kq, NULL, 0, &e, 1, &t);
   	if (r == -1) perror("dequeue fail");
   	if (r == 0) printf("event monitor timeout.\n");
   	if (r == 1) printf("dequeue success: ident=%lx.\n", e.ident);
   }
   
   int main()
   {
   	int kq = kqueue();
   	if (kq == -1) return -1;
   
   	enqueue(kq, 9, 100000003);
   	enqueue(kq, 8, 2);
   
   	dequeue(kq, 1);
   	dequeue(kq, 3);
   	dequeue(kq, 100000003);
   
   	return 0;
   }
   

7. Sjors cross-referenced this on Feb 22, 2018 from issue Clamp walletpassphrase timeout to 2^30 seconds and check its bounds by achow101
8. 
   AkioNak commented at 11:03 AM on February 22, 2018: contributor

   An idea to get rid of this restriction.

   1. walletpassphrase(): When calling RPCRunLater() , set the last parameter to min(nSleepTime, 100000000) instead of nSleepTime.
   2. LockWallet (): If current time still not have arrived to nRelockTime, call RPCRunLater() again with the last parameter to min(remain time, 100000000).
9. 
   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?

10. 
    AkioNak commented at 10:10 PM on February 22, 2018: contributor

    Yes, I think so.

11. sdaftuar cross-referenced this on Apr 6, 2018 from issue [qa] Ensure bitcoind processes are cleaned up when tests end by sdaftuar
12. 
    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?

13. MarcoFalke added the label Bug on Apr 6, 2018
14. MarcoFalke added this to the milestone 0.17.0 on Apr 6, 2018
15. sdaftuar cross-referenced this on Apr 6, 2018 from issue [rpcwallet] Clamp walletpassphrase value at 100M seconds by sdaftuar
16. MarcoFalke closed this on Apr 9, 2018

    ---

17. bitcoin locked this on Sep 8, 2021

Contributors

AkioNakSjorsachow101sdaftuar

Milestone
0.17.0