panic at end of checkpoint=1, secs=n runs

[elliefm]

Hi,

When running with "checkpoint=1", and "secs=n", I'm seeing this panic (output below) consistently for any value of n: it will run happily for n seconds, then panic.

I'm using nightlies of both dovecot core and imaptest:

• dovecot-20190509 (this looks like it's still the most recent?)
• imaptest-20190504 (a little old now, but commit history doesn't suggest anything relevant has changed since)

Is this expected? I would expect it to shutdown cleanly after n seconds (just as if the operator had pressed ^C, which works fine).

Note that it panics after n seconds of runtime (verified by running time imaptest ..., but not shown here), so I guess it's trying to shut itself down cleanly, but is tripping over something? (i.e. it does not seem to be panicking during the run, but rather during the shutdown)

If I run without "checkpoint=1" then it does shut itself down cleanly after n seconds.

(This is with Cyrus IMAPd as the IMAP server being tested, but I should not expect that to make any difference.)

Happy to provide further diagnostics/debug output/etc if you tell me what you need!

Cheers,

ellie

$"/home/ellie/build/imaptest-20190504/src/imaptest" "host=127.0.0.1" "port=9101" "user=cassandane" "user2=user2" "pass=testpw" "mbox=/home/ellie/fastmail/cassandane/data/dovecot-crlf" "rawlog" "secs=30" "checkpoint=1"
Logi List Stat Sele Fetc Fet2 Stor Dele Expu Appe Logo ChkP 
100%  50%  50% 100% 100% 100%  50% 100% 100% 100% 100% 100% 
                          30%                  5%           
  75   37   37   74   63   92   25   33   59   54   66    0   9/ 10
  65   35   30   64   62   85   18   35   63   54   64    8  10/ 10
  60   32   30   59   61   88   22   37   58   50   60    8  10/ 10
  60   25   33   62   61   90   23   37   65   40   60    7  10/ 10
  53   22   20   51   51   63   25   30   49   42   53    9  10/ 10
  42   22   20   44   46   57   15   30   43   28   42    6  10/ 10
  60   32   31   55   54   74   21   28   58   49   60    9  10/ 10
  59   29   37   61   60   89   25   30   59   45   59    4  10/ 10
  55   29   36   56   56   82   20   32   57   35   55    6  10/ 10
  60   31   32   62   62  101   20   35   59   48   60    7  10/ 10
   0    0   30   43   29   64   86   91   98  120    1    0 ms/cmd avg
Logi List Stat Sele Fetc Fet2 Stor Dele Expu Appe Logo ChkP 
100%  50%  50% 100% 100% 100%  50% 100% 100% 100% 100% 100% 
                          30%                  5%           
  60   31   30   58   58   81   18   31   59   45   60    9  10/ 10
  58   31   30   58   57   85   21   31   59   47   58    7  10/ 10
  53   27   25   52   53   70   25   33   53   39   53    7  10/ 10
  57   23   34   57   57   86   30   32   56   33   57    5  10/ 10
  51   24   25   53   50   62   17   25   52   25   51    6  10/ 10
  57   29   29   53   57   77   22   30   56   41   57    8  10/ 10
  56   29   28   61   60   87   26   40   57   33   56    4  10/ 10
  37   20   16   37   34   47   12   19   36   32   37    9  10/ 10
  42   19   19   39   43   58   18   23   44   34   42    9  10/ 10
  46   21   18   47   47   77   19   22   45   34   46    6  10/ 10
   0    0   30   48   38   76   97  105  115  146    1    0 ms/cmd avg
Logi List Stat Sele Fetc Fet2 Stor Dele Expu Appe Logo ChkP 
100%  50%  50% 100% 100% 100%  50% 100% 100% 100% 100% 100% 
                          30%                  5%           
  46   25   26   46   45   55   18   24   47   33   46    7  10/ 10
  48   23   26   49   47   70   14   26   46   36   48    7  10/ 10
  46   21   20   46   48   60   24   24   48   22   48    8  10/ 10
  55   24   30   56   57   78   18   22   53   35   53    6  10/ 10
  52   26   23   52   51   69   20   24   55   43   53    9   9/ 10
  43   25   23   43   44   77   16   20   42   27   42    8  10/ 10
  54   31   27   52   51   69   18   35   52   39   54    9  10/ 10
  52   28   36   54   54   69   22   31   54   33   53    7   9/ 10
  57   28   25   55   56   86   19   28   56   37   56    8  10/ 10
  51   25   21   52   49   75   17   30   51   39   51    7  10/ 10
Panic: file client-state.c: line 222 (client_update_plan): assertion failed: (client->plan_size == 0)
Error: Raw backtrace: /home/ellie/build/dovecot-20190509/src/lib-dovecot/.libs/libdovecot.so.0(+0xd7e21) [0x7fac472c5e21] -> /home/ellie/build/dovecot-20190509/src/lib-dovecot/.libs/libdovecot.so.0(+0xd7e61) [0x7fac472c5e61] -> /home/ellie/build/dovecot-20190509/src/lib-dovecot/.libs/libdovecot.so.0(i_fatal+0) [0x7fac472293b3] -> /home/ellie/build/imaptest-20190504/src/.libs/imaptest(imap_client_plan_send_more_commands+0x545) [0x556ad75e3dd5] -> /home/ellie/build/imaptest-20190504/src/.libs/imaptest(client_send_more_commands+0x24) [0x556ad75e1e94] -> /home/ellie/build/imaptest-20190504/src/.libs/imaptest(checkpoint_neg+0x588) [0x556ad75e07d8] -> /home/ellie/build/imaptest-20190504/src/.libs/imaptest(+0x10280) [0x556ad75e7280] -> /home/ellie/build/imaptest-20190504/src/.libs/imaptest(+0xab55) [0x556ad75e1b55] -> /home/ellie/build/dovecot-20190509/src/lib-dovecot/.libs/libdovecot.so.0(io_loop_call_io+0x75) [0x7fac472df155] -> /home/ellie/build/dovecot-20190509/src/lib-dovecot/.libs/libdovecot.so.0(io_loop_handler_run_internal+0x113) [0x7fac472e0b63] -> /home/ellie/build/dovecot-20190509/src/lib-dovecot/.libs/libdovecot.so.0(io_loop_handler_run+0x56) [0x7fac472df266] -> /home/ellie/build/dovecot-20190509/src/lib-dovecot/.libs/libdovecot.so.0(io_loop_run+0x38) [0x7fac472df478] -> /home/ellie/build/imaptest-20190504/src/.libs/imaptest(main+0x8b9) [0x556ad75df9b9] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7fac469672e1] -> /home/ellie/build/imaptest-20190504/src/.libs/imaptest(_start+0x2a) [0x556ad75e00ba]
Aborted

[elliefm]

As a workaround, I've stopped calling imaptest with the "secs=n" parameter and instead have arranged for the parent process to send the imaptest pid a SIGINT after the desired duration (i.e. trying to mimick the behaviour of pressing ^C in the controlling terminal, which consistently shuts down cleanly). But, to my surprise, it consistently panics like this, too.

I think, maybe, that this might indicate the presence/absence of a controlling terminal as being an important factor here?