cyrusimap / cassandane

Other
6 stars 11 forks source link

Intermitently failing tests #24

Closed jasontibbitts closed 6 years ago

jasontibbitts commented 7 years ago

I've found that at least test_references_chain(Cassandane::Cyrus::Thread) and test_replication_mailbox_new_enough(Cassandane::Cyrus::Replication) will sometimes pass and sometimes fail. They don't pass or fail together. As far as I can tell there are no dependency changes between the various builds.

I am calling testrunner.pl with various values for the '-j' option depending on the number of available CPUs, so I suspect there's a race somewhere, but I haven't been able to reproduce any of this on my personal build machine (12 threads, so '-j 12'). I've seen it on a builder with 6 threads and another with 48. I have a machine here I can use that has 56 threads that I can use for testing but I need to do some setup on it first.

Here is the full output from those tests. These come from different runs.

There was 1 failure:
1) test_references_chain(Cassandane::Cyrus::Thread)
 Structures begin differing at:
  $a->[0][1] = '4'
  $b->[0][1] = 'ARRAY(0x6307b78)'
 at Cassandane/Cyrus/Thread.pm line 179.
    Cassandane::Cyrus::Thread::test_references_chain(Cassandane::Cyrus::Thread=HASH(0x5aee260)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
    [...framework calls elided...]
Annotations:
=====> Cyrus::TestCase[567] ---------- BEGIN test_references_chain ----------
=====> Instance[1000] start main instance for test test_references_chain: basedir /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/140502B33
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/140502B33/conf/imapd.conf"
=====> Instance[451] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin
=====> Instance[451] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/libexec/cyrus-imapd
=====> Instance[912] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/140502B33 as 12846
=====> Instance[1755] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/140502B33/run/mux
=====> Instance[939] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/140502B33 as 12849
=====> Instance[451] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/libexec/cyrus-imapd
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/140502B33/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/140502B33/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/140502B33/conf/cyrus.conf"
=====> Instance[864] _start_master: waiting for PID file
=====> Instance[867] _start_master: PID file present and correct
=====> Instance[879] _start_master: PID waiting for services
=====> Daemon[358] is_listening: service imap is listening on 127.0.0.1:9115
=====> Util::Wait[77] Waited 0.070717 sec for 127.0.0.1:9115 to be in LISTEN state
=====> Instance[890] _start_master: all services listening
=====> Instance[966] create user cassandane
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9115
=====> Instance[1770] authdaemon connection: admin testpw imap 
=====> Instance[1031] started main instance for test test_references_chain: cyrus version 3.0.1-2.fc27 Fedora
=====> Cyrus::TestCase[574] Calling test function
=====> Cyrus::Thread[140] test THREAD with a linear chain of inter-message references
=====> Cyrus::Thread[141] and apparently similar subjects
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9115
=====> Instance[1770] authdaemon connection: cassandane testpw imap 
=====> Cyrus::Thread[145] append some messages
=====> Cyrus::Thread[168] check the messages got there
=====> Cyrus::TestCase[800] check_messages: 
=====> Cyrus::TestCase[821] message "Re: Re: portland"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "cosby sweater"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: portland"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: Re: Re: Re: cosby sweater"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: Re: cosby sweater"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: Re: Re: Re: brooklyn"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: Re: Re: Re: Re: brooklyn"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: Re: portland"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "brooklyn"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: Re: Re: cosby sweater"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: cosby sweater"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: Re: Re: brooklyn"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: brooklyn"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: Re: Re: portland"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: Re: Re: Re: Re: cosby sweater"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: Re: Re: Re: portland"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "portland"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: Re: brooklyn"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: brooklyn"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::TestCase[821] message "Re: Re: cosby sweater"
=====> Cyrus::TestCase[828] checking guid
=====> Cyrus::TestCase[836] checking header x-cassandane-unique
=====> Cyrus::TestCase[848] checking attribute uid
=====> Cyrus::Thread[173] The REFERENCES algorithm gives the true thread structure which is deep
=====> Cyrus::TestCase[681] Beginning tear_down
=====> Instance[1238] stop
=====> Instance[1200] _stop_pid: sending signal 15 to 12861
=====> Util::Wait[77] Waited 0.01015 sec for unknown condition
=====> Instance[915] killing saslauthd 12846
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 909.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 909.
=====> Instance[942] killing notifyd 12849
=====> Instance[915] killing saslauthd 12846
=====> Cyrus::TestCase[726] ---------- END test_references_chain ----------
=====> Daemon[387] checking for stray processes on ports: 9115
Test was not successful.
There was 1 error:
1) test_replication_mailbox_new_enough(Cassandane::Cyrus::Replication)
 Perl exception: child process (binary tar pid 19302) exited with code 2
 at Cassandane/Instance.pm line 1427.
    Cassandane::Instance::__ANON__(HASH(0x637ae88), 2) called at Cassandane/Instance.pm line 1609
    Cassandane::Instance::_handle_wait_status(Cassandane::Instance=HASH(0x5d23c30), 19302) called at Cassandane/Instance.pm line 1399
    Cassandane::Instance::reap_command(Cassandane::Instance=HASH(0x5d23c30), 19302) called at Cassandane/Instance.pm line 1389
    Cassandane::Instance::run_command(Cassandane::Instance=HASH(0x5d23c30), HASH(0x6c8d5f8), "tar", "-x", "-f", "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane-2f8f3f4949"..., "-C", "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/15561"...) called at Cassandane/Instance.pm line 1711
    Cassandane::Instance::unpackfile(Cassandane::Instance=HASH(0x5d23c30), "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane-2f8f3f4949"..., "data/user/cassandane") called at Cassandane/Instance.pm line 1927
    Cassandane::Instance::install_old_mailbox(Cassandane::Instance=HASH(0x5d23c30), "cassandane", 10) called at Cassandane/Cyrus/Replication.pm line 804
    Cassandane::Cyrus::Replication::test_replication_mailbox_new_enough(Cassandane::Cyrus::Replication=HASH(0x58ed8c8)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
    [...framework calls elided...]
Annotations:
=====> Cyrus::TestCase[567] ---------- BEGIN test_replication_mailbox_new_enough ----------
=====> Cyrus::TestCase[160] Magic word replication in name wants replica = 1
=====> Instance[1000] start main instance for test test_replication_mailbox_new_enough: basedir /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\11
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\11/conf/imapd.conf"
=====> Instance[451] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin
=====> Instance[451] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/libexec/cyrus-imapd
=====> Instance[912] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\11 as 18939
=====> Instance[1755] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\11/run/mux
=====> Instance[939] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\11 as 18941
chmod: cannot access '/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/15561311/run/mux': No such file or directory
=====> Instance[451] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/libexec/cyrus-imapd
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\11/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\11/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\11/conf/cyrus.conf"
=====> Instance[864] _start_master: waiting for PID file
=====> Instance[867] _start_master: PID file present and correct
=====> Instance[879] _start_master: PID waiting for services
=====> Daemon[358] is_listening: service imap is listening on 127.0.0.1:9376
=====> Util::Wait[77] Waited 0.077641 sec for 127.0.0.1:9376 to be in LISTEN state
=====> Instance[890] _start_master: all services listening
=====> Instance[966] create user cassandane
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9376
=====> Instance[1770] authdaemon connection: admin testpw imap 
=====> Instance[1031] started main instance for test test_replication_mailbox_new_enough: cyrus version 3.0.1-2.fc27 Fedora
=====> Instance[1000] start replica instance for test test_replication_mailbox_new_enough: basedir /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\12
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\12/conf/imapd.conf"
=====> Instance[451] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin
=====> Instance[451] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/libexec/cyrus-imapd
=====> Instance[451] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/libexec/cyrus-imapd
=====> Instance[912] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\12 as 19060
=====> Instance[1755] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\12/run/mux
=====> Instance[939] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\12 as 19065
chmod: cannot access '/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/15561312/run/mux': No such file or directory
=====> Instance[451] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/libexec/cyrus-imapd
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\12/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\12/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\12/conf/cyrus.conf"
=====> Instance[864] _start_master: waiting for PID file
=====> Instance[867] _start_master: PID file present and correct
=====> Instance[879] _start_master: PID waiting for services
=====> Daemon[358] is_listening: service imap is listening on 127.0.0.1:9377
=====> Util::Wait[77] Waited 0.082736 sec for 127.0.0.1:9377 to be in LISTEN state
=====> Daemon[358] is_listening: service sync is listening on 127.0.0.1:9375
=====> Instance[890] _start_master: all services listening
=====> Instance[1031] started replica instance for test test_replication_mailbox_new_enough: cyrus version 3.0.1-2.fc27 Fedora
=====> Cyrus::TestCase[942] running replication
=====> Instance[451] Found binary sync_client in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-2.fc27.x86_64/usr/sbin/sync_client" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\11/conf/imapd.conf" "-v" "-v" "-o" "-S" "127.0.0.1" "-u" "cassandane"
=====> Instance[1770] authdaemon connection: repluser replpass imap 
=====> Cyrus::TestCase[574] Calling test function
=====> Instance[1923] installing version 10 mailbox for user cassandane
=====> Instance[1501] Running: "tar" "-x" "-f" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane-2f8f3f4949e58bf20362c3cd8b1720f49002660d/data/old-mailboxes/version10.tar.gz" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\11/data/user/cassandane"
=====> Cyrus::TestCase[681] Beginning tear_down
=====> Instance[1238] stop
=====> Instance[1200] _stop_pid: sending signal 15 to 18966
=====> Util::Wait[77] Waited 0.010114 sec for unknown condition
=====> Instance[915] killing saslauthd 18939
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 909.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 909.
=====> Instance[942] killing notifyd 18941
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 936.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 936.
=====> Instance[915] killing saslauthd 18939
=====> Instance[1238] stop
=====> Instance[1200] _stop_pid: sending signal 15 to 19140
=====> Util::Wait[77] Waited 0.01011 sec for unknown condition
=====> Instance[915] killing saslauthd 19060
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 909.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 909.
=====> Instance[915] killing saslauthd 18939
=====> Instance[942] killing notifyd 18941
=====> Instance[942] killing notifyd 19065
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 936.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 936.
=====> Instance[915] killing saslauthd 18939
=====> Instance[942] killing notifyd 18941
=====> Instance[915] killing saslauthd 19060
=====> Cyrus::TestCase[726] ---------- END test_replication_mailbox_new_enough ----------
=====> Daemon[387] checking for stray processes on ports: 9375 9376 9377
Test was not successful.
elliefm commented 7 years ago
1) test_replication_mailbox_new_enough(Cassandane::Cyrus::Replication)
 Perl exception: child process (binary tar pid 19302) exited with code 2
 at Cassandane/Instance.pm line 1427.
    Cassandane::Instance::__ANON__(HASH(0x637ae88), 2) called at Cassandane/Instance.pm line 1609

I wonder if this one is due to the cassandane directory running out of disk space? The exit 2 from tar is supposedly for unrecoverable fatal errors. Cassandane runs churn up quite a bit of disk space (especially if not cleaned up between runs). You might try setting cleanup = yes in the cassandane.ini, or running testrunner.pl with the --cleanup argument, and see if this goes away?

Haven't looked into the test_references_chain failure yet, I'm not even sure what this suite tests so I have no gut feeling about what it might be

elliefm commented 7 years ago

For whatever it's worth, I do all my Cyrus work in a virtual machine with 2 virtual cores (running on a quad-core laptop), and I find that -j4 is about the sweet spot for that -- so two jobs per core.

jasontibbitts commented 7 years ago

Yeah, our build VMs don't always have a large amount of space, so that could explain that failure. I'll add --cleanup and see if that one reoccurs.

Here are two more intermittent failures, which happened on the s390x host. I don't think I've seen those fail before on any architecture.

If piling these together is problematic for you, please let me know and I'll separate them out. I just want to be able to have an upstream tracker for them to use as a reference as to why I have them disabled in my builds.

There were 2 errors:
1) test_mbox_replication_new_mas(Cassandane::Cyrus::Metadata)
 Perl exception: Cannot login to server "127.0.0.1:9104": IMAP Command : 'login' failed. Response was : no - Login failed: generic failure
 at Cassandane/IMAPMessageStore.pm line 111.
    Cassandane::IMAPMessageStore::connect(Cassandane::IMAPMessageStore=HASH(0x2049ba28)) called at Cassandane/IMAPMessageStore.pm line 290
    Cassandane::IMAPMessageStore::get_client(Cassandane::IMAPMessageStore=HASH(0x2049ba28)) called at Cassandane/Instance.pm line 973
    Cassandane::Instance::create_user(Cassandane::Instance=HASH(0x203df5e0), "cassandane") called at Cassandane/Instance.pm line 1025
    Cassandane::Instance::start(Cassandane::Instance=HASH(0x203df5e0)) called at Cassandane/Cyrus/TestCase.pm line 584
    Cassandane::Cyrus::TestCase::_start_instances(Cassandane::Cyrus::Metadata=HASH(0x1f1f3d90)) called at Cassandane/Cyrus/TestCase.pm line 571
    Cassandane::Cyrus::TestCase::set_up(Cassandane::Cyrus::Metadata=HASH(0x1f1f3d90)) called at Cassandane/Cyrus/Metadata.pm line 62
    Cassandane::Cyrus::Metadata::set_up(Cassandane::Cyrus::Metadata=HASH(0x1f1f3d90)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 58
    Test::Unit::TestCase::run_bare(Cassandane::Cyrus::Metadata=HASH(0x1f1f3d90)) called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 103
    Test::Unit::Result::__ANON__() called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 119
    Test::Unit::Result::run_protected(Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Cyrus::Metadata=HASH(0x1f1f3d90), CODE(0x203c86a0)) called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 107
    Test::Unit::Result::run(Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Cyrus::Metadata=HASH(0x1f1f3d90)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 51
    Test::Unit::TestCase::run(Cassandane::Cyrus::Metadata=HASH(0x1f1f3d90), Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Unit::RunnerPretty=HASH(0x1cdc7988)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestSuite.pm line 278
    Test::Unit::TestSuite::run(Test::Unit::TestSuite=HASH(0x1f014e90), Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Unit::RunnerPretty=HASH(0x1cdc7988)) called at Cassandane/Unit/TestPlan.pm line 749
    Cassandane::Unit::TestPlan::_run_workitem(Cassandane::Unit::TestPlan=HASH(0x1cdc78e0), HASH(0x2040f7a8), Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Unit::RunnerPretty=HASH(0x1cdc7988), 0) called at Cassandane/Unit/TestPlan.pm line 865
    Cassandane::Unit::TestPlan::__ANON__(HASH(0x2040f7a8)) called at Cassandane/Unit/TestPlan.pm line 207
    Cassandane::Unit::Worker::_mainloop(Cassandane::Unit::Worker=HASH(0x1fa230e8)) called at Cassandane/Unit/TestPlan.pm line 167
    Cassandane::Unit::Worker::start(Cassandane::Unit::Worker=HASH(0x1fa230e8)) called at Cassandane/Unit/TestPlan.pm line 312
    Cassandane::Unit::WorkerPool::start(Cassandane::Unit::WorkerPool=HASH(0x1fa23118)) called at Cassandane/Unit/TestPlan.pm line 869
    Cassandane::Unit::TestPlan::run(Cassandane::Unit::TestPlan=HASH(0x1cdc78e0), Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Unit::RunnerPretty=HASH(0x1cdc7988)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestRunner.pm line 54
    Test::Unit::TestRunner::do_run(Cassandane::Unit::RunnerPretty=HASH(0x1cdc7988), Cassandane::Unit::TestPlan=HASH(0x1cdc78e0), 0) called at ./testrunner.pl line 126
    main::__ANON__(Cassandane::Unit::TestPlan=HASH(0x1cdc78e0), GLOB(0x1cdc7838)) called at ./testrunner.pl line 300
Annotations:
=====> Cyrus::TestCase[567] ---------- BEGIN test_mbox_replication_new_mas ----------
=====> Cyrus::TestCase[160] Magic word replication in name wants replica = 1
=====> Instance[1000] start main instance for test test_mbox_replication_new_mas: basedir /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011A240
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011A240/conf/imapd.conf"
=====> Instance[451] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[451] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd
=====> Instance[912] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011A240 as 19214
=====> Instance[939] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011A240 as 19215
=====> Instance[451] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011A240/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011A240/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011A240/conf/cyrus.conf"
=====> Instance[864] _start_master: waiting for PID file
=====> Instance[867] _start_master: PID file present and correct
=====> Instance[879] _start_master: PID waiting for services
=====> Daemon[358] is_listening: service imap is listening on 127.0.0.1:9104
=====> Util::Wait[77] Waited 0.113941 sec for 127.0.0.1:9104 to be in LISTEN state
=====> Instance[890] _start_master: all services listening
=====> Instance[966] create user cassandane
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9104
=====> Instance[1755] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011A240/run/mux
=====> Daemon[387] checking for stray processes on ports: 9103 9104
2) test_motd(Cassandane::Cyrus::Metadata)
 Perl exception: Cannot login to server "127.0.0.1:9116": IMAP Command : 'login' failed. Response was : no - Login failed: generic failure
 at Cassandane/IMAPMessageStore.pm line 111.
    Cassandane::IMAPMessageStore::connect(Cassandane::IMAPMessageStore=HASH(0x20931008)) called at Cassandane/IMAPMessageStore.pm line 290
    Cassandane::IMAPMessageStore::get_client(Cassandane::IMAPMessageStore=HASH(0x20931008)) called at Cassandane/Instance.pm line 973
    Cassandane::Instance::create_user(Cassandane::Instance=HASH(0x1fa24c38), "cassandane") called at Cassandane/Instance.pm line 1025
    Cassandane::Instance::start(Cassandane::Instance=HASH(0x1fa24c38)) called at Cassandane/Cyrus/TestCase.pm line 584
    Cassandane::Cyrus::TestCase::_start_instances(Cassandane::Cyrus::Metadata=HASH(0x1f1f4f70)) called at Cassandane/Cyrus/TestCase.pm line 571
    Cassandane::Cyrus::TestCase::set_up(Cassandane::Cyrus::Metadata=HASH(0x1f1f4f70)) called at Cassandane/Cyrus/Metadata.pm line 62
    Cassandane::Cyrus::Metadata::set_up(Cassandane::Cyrus::Metadata=HASH(0x1f1f4f70)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 58
    Test::Unit::TestCase::run_bare(Cassandane::Cyrus::Metadata=HASH(0x1f1f4f70)) called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 103
    Test::Unit::Result::__ANON__() called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 119
    Test::Unit::Result::run_protected(Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Cyrus::Metadata=HASH(0x1f1f4f70), CODE(0x20936640)) called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 107
    Test::Unit::Result::run(Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Cyrus::Metadata=HASH(0x1f1f4f70)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 51
    Test::Unit::TestCase::run(Cassandane::Cyrus::Metadata=HASH(0x1f1f4f70), Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Unit::RunnerPretty=HASH(0x1cdc7988)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestSuite.pm line 278
    Test::Unit::TestSuite::run(Test::Unit::TestSuite=HASH(0x1f014e90), Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Unit::RunnerPretty=HASH(0x1cdc7988)) called at Cassandane/Unit/TestPlan.pm line 749
    Cassandane::Unit::TestPlan::_run_workitem(Cassandane::Unit::TestPlan=HASH(0x1cdc78e0), HASH(0x20951c58), Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Unit::RunnerPretty=HASH(0x1cdc7988), 0) called at Cassandane/Unit/TestPlan.pm line 865
    Cassandane::Unit::TestPlan::__ANON__(HASH(0x20951c58)) called at Cassandane/Unit/TestPlan.pm line 207
    Cassandane::Unit::Worker::_mainloop(Cassandane::Unit::Worker=HASH(0x1f9ecd30)) called at Cassandane/Unit/TestPlan.pm line 167
    Cassandane::Unit::Worker::start(Cassandane::Unit::Worker=HASH(0x1f9ecd30)) called at Cassandane/Unit/TestPlan.pm line 312
    Cassandane::Unit::WorkerPool::start(Cassandane::Unit::WorkerPool=HASH(0x1fa23118)) called at Cassandane/Unit/TestPlan.pm line 869
    Cassandane::Unit::TestPlan::run(Cassandane::Unit::TestPlan=HASH(0x1cdc78e0), Test::Unit::Result=HASH(0x1cdc7b20), Cassandane::Unit::RunnerPretty=HASH(0x1cdc7988)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestRunner.pm line 54
    Test::Unit::TestRunner::do_run(Cassandane::Unit::RunnerPretty=HASH(0x1cdc7988), Cassandane::Unit::TestPlan=HASH(0x1cdc78e0), 0) called at ./testrunner.pl line 126
    main::__ANON__(Cassandane::Unit::TestPlan=HASH(0x1cdc78e0), GLOB(0x1cdc7838)) called at ./testrunner.pl line 300
Annotations:
=====> Cyrus::TestCase[567] ---------- BEGIN test_motd ----------
=====> Instance[1000] start main instance for test test_motd: basedir /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011B120
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011B120/conf/imapd.conf"
=====> Instance[451] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[451] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd
=====> Instance[912] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011B120 as 19243
=====> Instance[939] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011B120 as 19244
=====> Instance[451] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011B120/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011B120/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011B120/conf/cyrus.conf"
=====> Instance[864] _start_master: waiting for PID file
=====> Instance[867] _start_master: PID file present and correct
=====> Instance[879] _start_master: PID waiting for services
=====> Daemon[358] is_listening: service imap is listening on 127.0.0.1:9116
=====> Util::Wait[77] Waited 0.048105 sec for 127.0.0.1:9116 to be in LISTEN state
=====> Instance[890] _start_master: all services listening
=====> Instance[966] create user cassandane
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9116
=====> Instance[1755] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/001011B120/run/mux
=====> Daemon[387] checking for stray processes on ports: 9116
Test was not successful.
jasontibbitts commented 7 years ago

There seems to be a recurring theme with the login failures. This failure just popped up on s390x only:

There was 1 error:
1) test_setmessages_destroy(Cassandane::Cyrus::JMAPMail)
 Perl exception: Cannot login to server "127.0.0.1:9103": IMAP Command : 'login' failed. Response was : no - Login failed: generic failure
 at Cassandane/IMAPMessageStore.pm line 111.
    Cassandane::IMAPMessageStore::connect(Cassandane::IMAPMessageStore=HASH(0x2d2def60)) called at Cassandane/IMAPMessageStore.pm line 290
    Cassandane::IMAPMessageStore::get_client(Cassandane::IMAPMessageStore=HASH(0x2d2def60)) called at Cassandane/Instance.pm line 973
    Cassandane::Instance::create_user(Cassandane::Instance=HASH(0x2d3786d0), "cassandane") called at Cassandane/Instance.pm line 1025
    Cassandane::Instance::start(Cassandane::Instance=HASH(0x2d3786d0)) called at Cassandane/Cyrus/TestCase.pm line 584
    Cassandane::Cyrus::TestCase::_start_instances(Cassandane::Cyrus::JMAPMail=HASH(0x2bcee0b0)) called at Cassandane/Cyrus/TestCase.pm line 571
    Cassandane::Cyrus::TestCase::set_up(Cassandane::Cyrus::JMAPMail=HASH(0x2bcee0b0)) called at Cassandane/Cyrus/JMAPMail.pm line 70
    Cassandane::Cyrus::JMAPMail::set_up(Cassandane::Cyrus::JMAPMail=HASH(0x2bcee0b0)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 58
    Test::Unit::TestCase::run_bare(Cassandane::Cyrus::JMAPMail=HASH(0x2bcee0b0)) called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 103
    Test::Unit::Result::__ANON__() called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 119
    Test::Unit::Result::run_protected(Test::Unit::Result=HASH(0x29c842c8), Cassandane::Cyrus::JMAPMail=HASH(0x2bcee0b0), CODE(0x2d24cae0)) called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 107
    Test::Unit::Result::run(Test::Unit::Result=HASH(0x29c842c8), Cassandane::Cyrus::JMAPMail=HASH(0x2bcee0b0)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 51
    Test::Unit::TestCase::run(Cassandane::Cyrus::JMAPMail=HASH(0x2bcee0b0), Test::Unit::Result=HASH(0x29c842c8), Cassandane::Unit::RunnerPretty=HASH(0x29c84130)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestSuite.pm line 278
    Test::Unit::TestSuite::run(Test::Unit::TestSuite=HASH(0x2b95fdc8), Test::Unit::Result=HASH(0x29c842c8), Cassandane::Unit::RunnerPretty=HASH(0x29c84130)) called at Cassandane/Unit/TestPlan.pm line 749
    Cassandane::Unit::TestPlan::_run_workitem(Cassandane::Unit::TestPlan=HASH(0x29c84010), HASH(0x2d1ecc30), Test::Unit::Result=HASH(0x29c842c8), Cassandane::Unit::RunnerPretty=HASH(0x29c84130), 0) called at Cassandane/Unit/TestPlan.pm line 865
    Cassandane::Unit::TestPlan::__ANON__(HASH(0x2d1ecc30)) called at Cassandane/Unit/TestPlan.pm line 207
    Cassandane::Unit::Worker::_mainloop(Cassandane::Unit::Worker=HASH(0x2c8dfff0)) called at Cassandane/Unit/TestPlan.pm line 167
    Cassandane::Unit::Worker::start(Cassandane::Unit::Worker=HASH(0x2c8dfff0)) called at Cassandane/Unit/TestPlan.pm line 312
    Cassandane::Unit::WorkerPool::start(Cassandane::Unit::WorkerPool=HASH(0x2c8e0020)) called at Cassandane/Unit/TestPlan.pm line 869
    Cassandane::Unit::TestPlan::run(Cassandane::Unit::TestPlan=HASH(0x29c84010), Test::Unit::Result=HASH(0x29c842c8), Cassandane::Unit::RunnerPretty=HASH(0x29c84130)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestRunner.pm line 54
    Test::Unit::TestRunner::do_run(Cassandane::Unit::RunnerPretty=HASH(0x29c84130), Cassandane::Unit::TestPlan=HASH(0x29c84010), 0) called at ./testrunner.pl line 126
    main::__ANON__(Cassandane::Unit::TestPlan=HASH(0x29c84010), GLOB(0x29c84040)) called at ./testrunner.pl line 300
Annotations:
=====> Cyrus::TestCase[567] ---------- BEGIN test_setmessages_destroy ----------
=====> Cyrus::TestCase[160] Magic attribute JMAP wants jmap = 1
=====> Cyrus::TestCase[160] Magic attribute JMAP wants adminstore = 1
=====> Cyrus::TestCase[160] Magic attribute JMAP wants services = ARRAY(0x2d1df6f8)
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config caldav_realm = Cassandane
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config conversations = yes
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config httpmodules = carddav caldav jmap
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config httpallowcompress = no
=====> Instance[1000] start main instance for test test_setmessages_destroy: basedir /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/185504A177
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/185504A177/conf/imapd.conf"
=====> Instance[451] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[451] Found binary httpd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd
=====> Instance[451] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd
=====> Instance[912] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/185504A177 as 789
=====> Instance[939] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/185504A177 as 790
=====> Instance[451] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/185504A177/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/185504A177/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/185504A177/conf/cyrus.conf"
=====> Instance[864] _start_master: waiting for PID file
=====> Instance[867] _start_master: PID file present and correct
=====> Instance[879] _start_master: PID waiting for services
=====> Daemon[358] is_listening: service http is listening on 127.0.0.1:9102
=====> Util::Wait[77] Waited 0.076262 sec for 127.0.0.1:9102 to be in LISTEN state
=====> Daemon[358] is_listening: service imap is listening on 127.0.0.1:9103
=====> Instance[890] _start_master: all services listening
=====> Instance[966] create user cassandane
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9103
=====> Instance[1755] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/185504A177/run/mux
=====> Daemon[387] checking for stray processes on ports: 9102 9103
There was 1 failure:
1) test_basic(Cassandane::Test::Metronome)
 Average 54.3154043265529 is outside expected range at /usr/share/perl5/vendor_perl/Test/Unit/Exception.pm line 13, <GEN1> line 333.
    Test::Unit::Exception::throw_new(Test::Unit::Failure=HASH(0x2d249298), "-package", "Cassandane::Test::Metronome", "-file", "Cassandane/Test/Metronome.pm", "-line", 82, "-object", ...) called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 85
    Test::Unit::Assert::do_assertion(Cassandane::Test::Metronome=HASH(0x2c8a9ba0), Test::Unit::Assertion::Boolean=SCALAR(0x2d429608), "Cassandane::Test::Metronome", "Cassandane/Test/Metronome.pm", 82, "Average 54.3154043265529 is outside expected range") called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 19
    Test::Unit::Assert::assert(Cassandane::Test::Metronome=HASH(0x2c8a9ba0), "", "Average 54.3154043265529 is outside expected range") called at Cassandane/Test/Metronome.pm line 82
    Cassandane::Test::Metronome::test_basic(Cassandane::Test::Metronome=HASH(0x2c8a9ba0)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
    [...framework calls elided...]
Annotations:
=====> Test::Metronome[73] Actual rate 81.3139051888171
=====> Test::Metronome[73] Actual rate 53.4137277534172
=====> Test::Metronome[73] Actual rate 80.039098686171
=====> Test::Metronome[73] Actual rate 106.696067540541
=====> Test::Metronome[73] Actual rate 94.138991433589
=====> Test::Metronome[73] Actual rate 105.270194396191
=====> Test::Metronome[73] Actual rate 95.7898956817949
=====> Test::Metronome[73] Actual rate 103.855942899931
=====> Test::Metronome[73] Actual rate 96.7200304342008
=====> Test::Metronome[73] Actual rate 102.336676877919
=====> Test::Metronome[73] Actual rate 87.3972657731558
=====> Test::Metronome[73] Actual rate 95.3118089693289
=====> Test::Metronome[73] Actual rate 103.247804472854
=====> Test::Metronome[73] Actual rate 89.3872964571987
=====> Test::Metronome[73] Actual rate 95.7431614474811
=====> Test::Metronome[73] Actual rate 102.105927516507
=====> Test::Metronome[73] Actual rate 97.8761527248408
=====> Test::Metronome[73] Actual rate 102.051186286818
=====> Test::Metronome[73] Actual rate 94.361322902884
=====> Test::Metronome[73] Actual rate 99.3011043962194
=====> Test::Metronome[73] Actual rate 100.634412575808
=====> Test::Metronome[73] Actual rate 99.363259434842
=====> Test::Metronome[73] Actual rate 93.3267143383991
=====> Test::Metronome[73] Actual rate 97.3693664043581
=====> Test::Metronome[73] Actual rate 101.422578511856
=====> Test::Metronome[73] Actual rate 97.9896905180333
=====> Test::Metronome[73] Actual rate 101.736372041399
=====> Test::Metronome[73] Actual rate 21.6352221525268
=====> Test::Metronome[73] Actual rate 22.4050910067387
=====> Test::Metronome[73] Actual rate 23.1775091132789
=====> Test::Metronome[73] Actual rate 23.9499453774116
=====> Test::Metronome[73] Actual rate 24.7223774363481
=====> Test::Metronome[73] Actual rate 25.4948035123925
=====> Test::Metronome[73] Actual rate 26.2672209285433
=====> Test::Metronome[73] Actual rate 27.039629927301
=====> Test::Metronome[73] Actual rate 27.8120269735733
=====> Test::Metronome[73] Actual rate 28.5844178006283
=====> Test::Metronome[73] Actual rate 29.3567962209078
=====> Test::Metronome[73] Actual rate 30.129170068615
=====> Test::Metronome[73] Actual rate 30.9015339133161
=====> Test::Metronome[73] Actual rate 31.6738875350979
=====> Test::Metronome[73] Actual rate 32.4462331051732
=====> Test::Metronome[73] Actual rate 33.2185668202697
=====> Test::Metronome[73] Actual rate 33.9908956931964
=====> Test::Metronome[73] Actual rate 34.7632160373749
=====> Test::Metronome[73] Actual rate 35.5355283637164
=====> Test::Metronome[73] Actual rate 36.3078281315999
=====> Test::Metronome[73] Actual rate 37.0801213203468
=====> Test::Metronome[73] Actual rate 37.8524047048981
=====> Test::Metronome[73] Actual rate 38.6246816761516
=====> Test::Metronome[73] Actual rate 39.39694753914
=====> Test::Metronome[73] Actual rate 40.1691911790869
=====> Test::Metronome[73] Actual rate 40.9414369543106
=====> Test::Metronome[73] Actual rate 41.7136758566311
=====> Test::Metronome[73] Actual rate 42.4859038476357
=====> Test::Metronome[73] Actual rate 43.2581258918342
=====> Test::Metronome[73] Actual rate 44.0303309393828
=====> Test::Metronome[73] Actual rate 44.7989938396312
=====> Test::Metronome[73] Actual rate 45.57096783012
=====> Test::Metronome[73] Actual rate 46.3430585196156
=====> Test::Metronome[73] Actual rate 47.1151347183657
=====> Test::Metronome[73] Actual rate 47.8872302367283
=====> Test::Metronome[73] Actual rate 48.6593167456339
=====> Test::Metronome[73] Actual rate 49.431398518755
=====> Test::Metronome[73] Actual rate 50.2034680708684
=====> Test::Metronome[73] Actual rate 50.9755314873607
=====> Test::Metronome[73] Actual rate 51.7475881960625
=====> Test::Metronome[73] Actual rate 52.519635618173
=====> Test::Metronome[73] Actual rate 53.2916712472324
=====> Test::Metronome[73] Actual rate 54.0636977212012
=====> Test::Metronome[73] Actual rate 54.8357158241003
=====> Test::Metronome[73] Actual rate 55.6077271843157
=====> Test::Metronome[73] Actual rate 56.3797230563615
=====> Test::Metronome[73] Actual rate 57.1517194099925
=====> Test::Metronome[73] Actual rate 57.9227128630404
=====> Test::Metronome[73] Actual rate 58.6946664407523
=====> Test::Metronome[73] Actual rate 59.4666217811493
=====> Test::Metronome[73] Actual rate 60.2385731582354
=====> Test::Metronome[73] Actual rate 61.01051295104
=====> Test::Metronome[73] Actual rate 61.7824474075879
=====> Test::Metronome[73] Actual rate 62.5543713955479
=====> Test::Metronome[73] Actual rate 63.3262895886355
=====> Test::Metronome[73] Actual rate 64.0981985009701
=====> Test::Metronome[73] Actual rate 64.8700977861292
=====> Test::Metronome[73] Actual rate 65.6419868933095
=====> Test::Metronome[73] Actual rate 66.4138658204868
=====> Test::Metronome[73] Actual rate 67.1857365490159
=====> Test::Metronome[73] Actual rate 67.9575965102725
=====> Test::Metronome[73] Actual rate 68.7294491968296
=====> Test::Metronome[73] Actual rate 69.5012959617242
=====> Test::Metronome[73] Actual rate 70.2731329089665
=====> Test::Metronome[73] Actual rate 71.0449618431746
=====> Test::Metronome[73] Actual rate 71.8167813432684
=====> Test::Metronome[73] Actual rate 72.5885913877604
=====> Test::Metronome[73] Actual rate 73.3603917441271
=====> Test::Metronome[73] Actual rate 74.1321856363892
=====> Test::Metronome[73] Actual rate 74.9039661888364
=====> Test::Metronome[73] Actual rate 75.6757406073508
=====> Test::Metronome[73] Actual rate 76.4475094700974
=====> Test::Metronome[73] Actual rate 77.2192700432243
=====> Test::Metronome[79] Rates: count 81 minimum 21.6352221525268 maximum 101.736372041399 average 54.3154043265529 sample_deviation 21.5083349767319
Test was not successful.
jasontibbitts commented 7 years ago

Ugh, I'm just trying to get one build through. Here's another attempt. This one has an instance of the "cannot login to server" problem, as well as two tests that seem to be performance-related: test_maxforkrate(Cassandane::Cyrus::Master) and test_basic(Cassandane::Test::Metronome). I'm not sure how a sufficiently slow machine could pass them. Maybe I should just disable them?

Run: 577, Failures: 2, Errors: 1
There was 1 error:
1) test_import_setdate(Cassandane::Cyrus::JMAPMail)
 Perl exception: Cannot login to server "127.0.0.1:9108": IMAP Command : 'login' failed. Response was : no - Login failed: generic failure
 at Cassandane/IMAPMessageStore.pm line 111.
    Cassandane::IMAPMessageStore::connect(Cassandane::IMAPMessageStore=HASH(0x7ed64f8)) called at Cassandane/IMAPMessageStore.pm line 290
    Cassandane::IMAPMessageStore::get_client(Cassandane::IMAPMessageStore=HASH(0x7ed64f8)) called at Cassandane/Instance.pm line 973
    Cassandane::Instance::create_user(Cassandane::Instance=HASH(0x7ea63b0), "cassandane") called at Cassandane/Instance.pm line 1025
    Cassandane::Instance::start(Cassandane::Instance=HASH(0x7ea63b0)) called at Cassandane/Cyrus/TestCase.pm line 584
    Cassandane::Cyrus::TestCase::_start_instances(Cassandane::Cyrus::JMAPMail=HASH(0x63ed3e0)) called at Cassandane/Cyrus/TestCase.pm line 571
    Cassandane::Cyrus::TestCase::set_up(Cassandane::Cyrus::JMAPMail=HASH(0x63ed3e0)) called at Cassandane/Cyrus/JMAPMail.pm line 70
    Cassandane::Cyrus::JMAPMail::set_up(Cassandane::Cyrus::JMAPMail=HASH(0x63ed3e0)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 58
    Test::Unit::TestCase::run_bare(Cassandane::Cyrus::JMAPMail=HASH(0x63ed3e0)) called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 103
    Test::Unit::Result::__ANON__() called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 119
    Test::Unit::Result::run_protected(Test::Unit::Result=HASH(0x4388f08), Cassandane::Cyrus::JMAPMail=HASH(0x63ed3e0), CODE(0x7ec0d78)) called at /usr/share/perl5/vendor_perl/Test/Unit/Result.pm line 107
    Test::Unit::Result::run(Test::Unit::Result=HASH(0x4388f08), Cassandane::Cyrus::JMAPMail=HASH(0x63ed3e0)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 51
    Test::Unit::TestCase::run(Cassandane::Cyrus::JMAPMail=HASH(0x63ed3e0), Test::Unit::Result=HASH(0x4388f08), Cassandane::Unit::RunnerPretty=HASH(0x4388d70)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestSuite.pm line 278
    Test::Unit::TestSuite::run(Test::Unit::TestSuite=HASH(0x60644a8), Test::Unit::Result=HASH(0x4388f08), Cassandane::Unit::RunnerPretty=HASH(0x4388d70)) called at Cassandane/Unit/TestPlan.pm line 749
    Cassandane::Unit::TestPlan::_run_workitem(Cassandane::Unit::TestPlan=HASH(0x4388c50), HASH(0x7ed4030), Test::Unit::Result=HASH(0x4388f08), Cassandane::Unit::RunnerPretty=HASH(0x4388d70), 0) called at Cassandane/Unit/TestPlan.pm line 865
    Cassandane::Unit::TestPlan::__ANON__(HASH(0x7ed4030)) called at Cassandane/Unit/TestPlan.pm line 207
    Cassandane::Unit::Worker::_mainloop(Cassandane::Unit::Worker=HASH(0x6fe4b40)) called at Cassandane/Unit/TestPlan.pm line 167
    Cassandane::Unit::Worker::start(Cassandane::Unit::Worker=HASH(0x6fe4b40)) called at Cassandane/Unit/TestPlan.pm line 312
    Cassandane::Unit::WorkerPool::start(Cassandane::Unit::WorkerPool=HASH(0x6fe4b70)) called at Cassandane/Unit/TestPlan.pm line 869
    Cassandane::Unit::TestPlan::run(Cassandane::Unit::TestPlan=HASH(0x4388c50), Test::Unit::Result=HASH(0x4388f08), Cassandane::Unit::RunnerPretty=HASH(0x4388d70)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestRunner.pm line 54
    Test::Unit::TestRunner::do_run(Cassandane::Unit::RunnerPretty=HASH(0x4388d70), Cassandane::Unit::TestPlan=HASH(0x4388c50), 0) called at ./testrunner.pl line 126
    main::__ANON__(Cassandane::Unit::TestPlan=HASH(0x4388c50), GLOB(0x4388c80)) called at ./testrunner.pl line 300
Annotations:
=====> Cyrus::TestCase[567] ---------- BEGIN test_import_setdate ----------
=====> Cyrus::TestCase[160] Magic attribute JMAP wants jmap = 1
=====> Cyrus::TestCase[160] Magic attribute JMAP wants adminstore = 1
=====> Cyrus::TestCase[160] Magic attribute JMAP wants services = ARRAY(0x7ea9260)
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config caldav_realm = Cassandane
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config conversations = yes
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config httpmodules = carddav caldav jmap
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config httpallowcompress = no
=====> Instance[1000] start main instance for test test_import_setdate: basedir /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016A95
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016A95/conf/imapd.conf"
=====> Instance[451] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[451] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd
=====> Instance[451] Found binary httpd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd
=====> Instance[912] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016A95 as 34554
=====> Instance[939] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016A95 as 34555
=====> Instance[451] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016A95/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016A95/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016A95/conf/cyrus.conf"
=====> Instance[864] _start_master: waiting for PID file
=====> Instance[867] _start_master: PID file present and correct
=====> Instance[879] _start_master: PID waiting for services
=====> Daemon[358] is_listening: service imap is listening on 127.0.0.1:9108
=====> Util::Wait[77] Waited 0.059967 sec for 127.0.0.1:9108 to be in LISTEN state
=====> Daemon[358] is_listening: service http is listening on 127.0.0.1:9109
=====> Instance[890] _start_master: all services listening
=====> Instance[966] create user cassandane
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9108
=====> Instance[1755] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016A95/run/mux
=====> Daemon[387] checking for stray processes on ports: 9108 9109
There were 2 failures:
1) test_maxforkrate(Cassandane::Cyrus::Master)
 Fork rate too slow, for 5.36904372524781 wanted 10 at /usr/share/perl5/vendor_perl/Test/Unit/Exception.pm line 13.
    Test::Unit::Exception::throw_new(Test::Unit::Failure=HASH(0x79edf78), "-package", "Cassandane::Cyrus::Master", "-file", "Cassandane/Cyrus/Master.pm", "-line", 819, "-object", ...) called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 85
    Test::Unit::Assert::do_assertion(Cassandane::Cyrus::Master=HASH(0x64eb588), Test::Unit::Assertion::Boolean=SCALAR(0x7786e98), "Cassandane::Cyrus::Master", "Cassandane/Cyrus/Master.pm", 819, "Fork rate too slow, for 5.36904372524781 wanted 10") called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 19
    Test::Unit::Assert::assert(Cassandane::Cyrus::Master=HASH(0x64eb588), "", "Fork rate too slow, for 5.36904372524781 wanted 10") called at Cassandane/Cyrus/Master.pm line 819
    Cassandane::Cyrus::Master::test_maxforkrate(Cassandane::Cyrus::Master=HASH(0x64eb588)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
    [...framework calls elided...]
Annotations:
=====> Cyrus::TestCase[567] ---------- BEGIN test_maxforkrate ----------
=====> Cyrus::TestCase[574] Calling test function
=====> Cyrus::Master[797] Testing enforcement of the maxforkrate= parameter
=====> Instance[1000] start unknown: basedir /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016B198
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[451] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016B198/conf/imapd.conf"
=====> Instance[912] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016B198 as 35523
=====> Instance[939] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016B198 as 35524
=====> Instance[1755] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016B198/run/mux
=====> Instance[451] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd
=====> Instance[1501] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.1-3.fc27.s390x/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016B198/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016B198/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016B198/conf/cyrus.conf"
=====> Instance[864] _start_master: waiting for PID file
=====> Instance[867] _start_master: PID file present and correct
=====> Instance[879] _start_master: PID waiting for services
=====> Daemon[358] is_listening: service B is listening on 127.0.0.1:9111
=====> Daemon[358] is_listening: service A is listening on 127.0.0.1:9112
=====> Instance[890] _start_master: all services listening
=====> Instance[1031] started unknown: cyrus version 3.0.1-3.fc27 Fedora
=====> Cyrus::Master[812] not preforked, so no lemmings running yet
=====> Cyrus::Master[816] Test that we can achieve the fast forks rate on the unlimited service
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9112
=====> Util::Wait[77] Waited 0.055556 sec for master to reap lemming 35542
=====> Util::Wait[77] Waited 0.0101 sec for master to reap lemming 35544
=====> Util::Wait[77] Waited 0.010088 sec for master to reap lemming 35548
=====> Util::Wait[77] Waited 0.010083 sec for master to reap lemming 35550
=====> Util::Wait[77] Waited 0.793476 sec for master to reap lemming 35552
=====> Util::Wait[77] Waited 0.017162 sec for master to reap lemming 35556
=====> Util::Wait[77] Waited 0.010087 sec for master to reap lemming 35563
=====> Util::Wait[77] Waited 0.010083 sec for master to reap lemming 35569
=====> Util::Wait[77] Waited 0.010087 sec for master to reap lemming 35571
=====> Util::Wait[77] Waited 0.010103 sec for master to reap lemming 35575
=====> Util::Wait[77] Waited 0.010093 sec for master to reap lemming 35578
=====> Util::Wait[77] Waited 0.010091 sec for master to reap lemming 35579
=====> Util::Wait[77] Waited 0.239023 sec for master to reap lemming 35580
=====> Util::Wait[77] Waited 0.019237 sec for master to reap lemming 35581
=====> Util::Wait[77] Waited 0.011059 sec for master to reap lemming 35584
=====> Util::Wait[77] Waited 0.010085 sec for master to reap lemming 35587
=====> Util::Wait[77] Waited 0.010303 sec for master to reap lemming 35588
=====> Util::Wait[77] Waited 0.013925 sec for master to reap lemming 35592
=====> Util::Wait[77] Waited 0.012171 sec for master to reap lemming 35595
=====> Util::Wait[77] Waited 0.010614 sec for master to reap lemming 35598
=====> Util::Wait[77] Waited 0.010677 sec for master to reap lemming 35600
=====> Util::Wait[77] Waited 0.062376 sec for master to reap lemming 35603
=====> Util::Wait[77] Waited 0.012341 sec for master to reap lemming 35604
=====> Util::Wait[77] Waited 0.010329 sec for master to reap lemming 35605
=====> Util::Wait[77] Waited 0.016811 sec for master to reap lemming 35607
=====> Util::Wait[77] Waited 0.010188 sec for master to reap lemming 35609
=====> Util::Wait[77] Waited 3.925189 sec for master to reap lemming 35611
=====> Util::Wait[77] Waited 0.012587 sec for master to reap lemming 35614
=====> Util::Wait[77] Waited 0.010085 sec for master to reap lemming 35616
=====> Util::Wait[77] Waited 0.010072 sec for master to reap lemming 35620
=====> Util::Wait[77] Waited 0.010073 sec for master to reap lemming 35621
=====> Util::Wait[77] Waited 0.010081 sec for master to reap lemming 35623
=====> Util::Wait[77] Waited 0.010079 sec for master to reap lemming 35627
=====> Util::Wait[77] Waited 0.012656 sec for master to reap lemming 35629
=====> Util::Wait[77] Waited 0.010081 sec for master to reap lemming 35633
=====> Util::Wait[77] Waited 0.015371 sec for master to reap lemming 35636
=====> Util::Wait[77] Waited 0.014498 sec for master to reap lemming 35637
=====> Util::Wait[77] Waited 0.010327 sec for master to reap lemming 35639
=====> Util::Wait[77] Waited 0.010081 sec for master to reap lemming 35641
=====> Util::Wait[77] Waited 0.018287 sec for master to reap lemming 35642
=====> Util::Wait[77] Waited 0.010087 sec for master to reap lemming 35643
=====> Util::Wait[77] Waited 0.010201 sec for master to reap lemming 35644
=====> Util::Wait[77] Waited 0.081146 sec for master to reap lemming 35645
=====> Util::Wait[77] Waited 0.014497 sec for master to reap lemming 35646
=====> Util::Wait[77] Waited 0.091985 sec for master to reap lemming 35647
=====> Util::Wait[77] Waited 0.450302 sec for master to reap lemming 35648
=====> Util::Wait[77] Waited 0.01019 sec for master to reap lemming 35649
=====> Util::Wait[77] Waited 0.057023 sec for master to reap lemming 35650
=====> Util::Wait[77] Waited 0.680629 sec for master to reap lemming 35651
=====> Util::Wait[77] Waited 0.010094 sec for master to reap lemming 35652
=====> Util::Wait[77] Waited 0.010082 sec for master to reap lemming 35654
=====> Util::Wait[77] Waited 0.010076 sec for master to reap lemming 35658
=====> Util::Wait[77] Waited 0.010077 sec for master to reap lemming 35660
=====> Util::Wait[77] Waited 0.010082 sec for master to reap lemming 35661
=====> Util::Wait[77] Waited 0.010094 sec for master to reap lemming 35662
=====> Util::Wait[77] Waited 0.010081 sec for master to reap lemming 35669
=====> Util::Wait[77] Waited 0.010081 sec for master to reap lemming 35671
=====> Util::Wait[77] Waited 0.010409 sec for master to reap lemming 35672
=====> Util::Wait[77] Waited 0.010082 sec for master to reap lemming 35673
=====> Util::Wait[77] Waited 0.010555 sec for master to reap lemming 35675
=====> Util::Wait[77] Waited 0.013543 sec for master to reap lemming 35677
=====> Util::Wait[77] Waited 0.024732 sec for master to reap lemming 35679
=====> Util::Wait[77] Waited 0.052034 sec for master to reap lemming 35680
=====> Util::Wait[77] Waited 0.09084 sec for master to reap lemming 35681
=====> Util::Wait[77] Waited 0.018046 sec for master to reap lemming 35683
=====> Util::Wait[77] Waited 0.552624 sec for master to reap lemming 35684
=====> Util::Wait[77] Waited 0.010101 sec for master to reap lemming 35685
=====> Util::Wait[77] Waited 0.010082 sec for master to reap lemming 35686
=====> Util::Wait[77] Waited 0.010254 sec for master to reap lemming 35687
=====> Util::Wait[77] Waited 0.011692 sec for master to reap lemming 35689
=====> Util::Wait[77] Waited 0.010072 sec for master to reap lemming 35690
=====> Util::Wait[77] Waited 0.010083 sec for master to reap lemming 35691
=====> Util::Wait[77] Waited 0.010141 sec for master to reap lemming 35692
=====> Util::Wait[77] Waited 0.010077 sec for master to reap lemming 35693
=====> Util::Wait[77] Waited 0.010079 sec for master to reap lemming 35694
=====> Util::Wait[77] Waited 0.010218 sec for master to reap lemming 35696
=====> Util::Wait[77] Waited 0.010187 sec for master to reap lemming 35698
=====> Util::Wait[77] Waited 0.010081 sec for master to reap lemming 35733
=====> Util::Wait[77] Waited 0.015629 sec for master to reap lemming 35736
=====> Util::Wait[77] Waited 0.013127 sec for master to reap lemming 35742
=====> Util::Wait[77] Waited 0.015474 sec for master to reap lemming 35745
=====> Util::Wait[77] Waited 0.154266 sec for master to reap lemming 35755
=====> Util::Wait[77] Waited 0.011422 sec for master to reap lemming 35758
=====> Util::Wait[77] Waited 0.210871 sec for master to reap lemming 35762
=====> Util::Wait[77] Waited 0.010126 sec for master to reap lemming 35765
=====> Util::Wait[77] Waited 0.0422 sec for master to reap lemming 35767
=====> Util::Wait[77] Waited 0.011339 sec for master to reap lemming 35793
=====> Util::Wait[77] Waited 0.01009 sec for master to reap lemming 35796
=====> Util::Wait[77] Waited 0.010227 sec for master to reap lemming 35798
=====> Util::Wait[77] Waited 0.010293 sec for master to reap lemming 35804
=====> Util::Wait[77] Waited 0.010067 sec for master to reap lemming 35805
=====> Util::Wait[77] Waited 0.141799 sec for master to reap lemming 35806
=====> Util::Wait[77] Waited 0.016552 sec for master to reap lemming 35807
=====> Util::Wait[77] Waited 0.01131 sec for master to reap lemming 35808
=====> Util::Wait[77] Waited 0.015591 sec for master to reap lemming 35809
=====> Util::Wait[77] Waited 0.015515 sec for master to reap lemming 35810
=====> Util::Wait[77] Waited 0.01523 sec for master to reap lemming 35811
=====> Util::Wait[77] Waited 0.010103 sec for master to reap lemming 35812
=====> Util::Wait[77] Waited 0.011341 sec for master to reap lemming 35813
=====> Util::Wait[77] Waited 0.010081 sec for master to reap lemming 35814
=====> Cyrus::Master[818] Actual rate: 5.36904372524781
=====> Cyrus::TestCase[681] Beginning tear_down
=====> Instance[1238] stop
=====> Instance[1200] _stop_pid: sending signal 15 to 35537
=====> Util::Wait[77] Waited 0.010446 sec for unknown condition
=====> Instance[915] killing saslauthd 35523
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 909.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 909.
=====> Instance[942] killing notifyd 35524
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 936.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 936.
=====> Instance[915] killing saslauthd 35523
=====> Instance[1266] Cleaning up basedir /builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/195016B198
=====> Cyrus::TestCase[726] ---------- END test_maxforkrate ----------
=====> Daemon[387] checking for stray processes on ports: 9111 9112
2) test_basic(Cassandane::Test::Metronome)
 Average 88.731389736976 is outside expected range at /usr/share/perl5/vendor_perl/Test/Unit/Exception.pm line 13, <GEN3> line 334.
    Test::Unit::Exception::throw_new(Test::Unit::Failure=HASH(0x77a18b8), "-package", "Cassandane::Test::Metronome", "-file", "Cassandane/Test/Metronome.pm", "-line", 82, "-object", ...) called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 85
    Test::Unit::Assert::do_assertion(Cassandane::Test::Metronome=HASH(0x6fae190), Test::Unit::Assertion::Boolean=SCALAR(0x7cc0c98), "Cassandane::Test::Metronome", "Cassandane/Test/Metronome.pm", 82, "Average 88.731389736976 is outside expected range") called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 19
    Test::Unit::Assert::assert(Cassandane::Test::Metronome=HASH(0x6fae190), "", "Average 88.731389736976 is outside expected range") called at Cassandane/Test/Metronome.pm line 82
    Cassandane::Test::Metronome::test_basic(Cassandane::Test::Metronome=HASH(0x6fae190)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
    [...framework calls elided...]
Annotations:
=====> Test::Metronome[73] Actual rate 73.2523159846878
=====> Test::Metronome[73] Actual rate 121.679658281255
=====> Test::Metronome[73] Actual rate 89.1761262459526
=====> Test::Metronome[73] Actual rate 64.7654164579179
=====> Test::Metronome[73] Actual rate 80.8959544361585
=====> Test::Metronome[73] Actual rate 97.0622705949477
=====> Test::Metronome[73] Actual rate 45.1281801559609
=====> Test::Metronome[73] Actual rate 51.5356878506535
=====> Test::Metronome[73] Actual rate 57.9745949625937
=====> Test::Metronome[73] Actual rate 64.4133728831355
=====> Test::Metronome[73] Actual rate 70.8516762603971
=====> Test::Metronome[73] Actual rate 77.2895108247528
=====> Test::Metronome[73] Actual rate 83.7268525587796
=====> Test::Metronome[73] Actual rate 90.163651803913
=====> Test::Metronome[73] Actual rate 96.5998985475175
=====> Test::Metronome[73] Actual rate 103.035637005614
=====> Test::Metronome[73] Actual rate 97.2518282563883
=====> Test::Metronome[73] Actual rate 102.702126854361
=====> Test::Metronome[73] Actual rate 81.7842506521032
=====> Test::Metronome[73] Actual rate 86.0539928621406
=====> Test::Metronome[73] Actual rate 90.3268009545681
=====> Test::Metronome[73] Actual rate 94.6240706080998
=====> Test::Metronome[73] Actual rate 98.9215529018588
=====> Test::Metronome[73] Actual rate 56.3767918830855
=====> Test::Metronome[73] Actual rate 58.7047811628521
=====> Test::Metronome[73] Actual rate 61.0516196331292
=====> Test::Metronome[73] Actual rate 63.398562345726
=====> Test::Metronome[73] Actual rate 65.7454741276818
=====> Test::Metronome[73] Actual rate 68.0923155908014
=====> Test::Metronome[73] Actual rate 70.4390945166675
=====> Test::Metronome[73] Actual rate 72.785782443711
=====> Test::Metronome[73] Actual rate 75.1323775289462
=====> Test::Metronome[73] Actual rate 77.4788996610352
=====> Test::Metronome[73] Actual rate 79.8253452446505
=====> Test::Metronome[73] Actual rate 82.1717273994652
=====> Test::Metronome[73] Actual rate 84.5180118940914
=====> Test::Metronome[73] Actual rate 86.8642190152887
=====> Test::Metronome[73] Actual rate 89.2103142378181
=====> Test::Metronome[73] Actual rate 91.556352047862
=====> Test::Metronome[73] Actual rate 93.9023157663639
=====> Test::Metronome[73] Actual rate 96.248203261732
=====> Test::Metronome[73] Actual rate 98.5939989871331
=====> Test::Metronome[73] Actual rate 100.939715008109
=====> Test::Metronome[73] Actual rate 99.0798048113192
=====> Test::Metronome[73] Actual rate 100.895165913363
=====> Test::Metronome[73] Actual rate 99.1207705554559
=====> Test::Metronome[73] Actual rate 100.857588218888
=====> Test::Metronome[73] Actual rate 98.5257688607433
=====> Test::Metronome[73] Actual rate 100.568010183448
=====> Test::Metronome[73] Actual rate 99.4326713341041
=====> Test::Metronome[73] Actual rate 100.538406599919
=====> Test::Metronome[73] Actual rate 99.3766900026068
=====> Test::Metronome[73] Actual rate 100.605528080363
=====> Test::Metronome[73] Actual rate 99.3827927134774
=====> Test::Metronome[73] Actual rate 100.597898106651
=====> Test::Metronome[73] Actual rate 99.4048621197692
=====> Test::Metronome[73] Actual rate 100.576804414608
=====> Test::Metronome[73] Actual rate 68.5598544912505
=====> Test::Metronome[73] Actual rate 69.7282845677304
=====> Test::Metronome[73] Actual rate 70.9093490994338
=====> Test::Metronome[73] Actual rate 72.0904886450525
=====> Test::Metronome[73] Actual rate 73.2716346834495
=====> Test::Metronome[73] Actual rate 74.452750096604
=====> Test::Metronome[73] Actual rate 75.6338599212167
=====> Test::Metronome[73] Actual rate 76.8149463145133
=====> Test::Metronome[73] Actual rate 77.9960150988492
=====> Test::Metronome[73] Actual rate 79.1770619981744
=====> Test::Metronome[73] Actual rate 80.358087954726
=====> Test::Metronome[73] Actual rate 81.5391076082786
=====> Test::Metronome[73] Actual rate 82.720102852392
=====> Test::Metronome[73] Actual rate 83.9010782409429
=====> Test::Metronome[73] Actual rate 85.0820326937139
=====> Test::Metronome[73] Actual rate 86.2629671567097
=====> Test::Metronome[73] Actual rate 87.4438872471053
=====> Test::Metronome[73] Actual rate 88.6219937421812
=====> Test::Metronome[73] Actual rate 89.802797403145
=====> Test::Metronome[73] Actual rate 90.9836086595722
=====> Test::Metronome[73] Actual rate 92.1643831110942
=====> Test::Metronome[73] Actual rate 93.345162056606
=====> Test::Metronome[73] Actual rate 94.5259295193325
=====> Test::Metronome[73] Actual rate 95.706667622709
=====> Test::Metronome[73] Actual rate 96.8873918152933
=====> Test::Metronome[73] Actual rate 98.0680838897269
=====> Test::Metronome[73] Actual rate 99.2487677802201
=====> Test::Metronome[73] Actual rate 100.429419622918
=====> Test::Metronome[73] Actual rate 98.864131649584
=====> Test::Metronome[73] Actual rate 100.007179286812
=====> Test::Metronome[73] Actual rate 94.501970331078
=====> Test::Metronome[73] Actual rate 95.5530704837091
=====> Test::Metronome[73] Actual rate 96.6252181228108
=====> Test::Metronome[73] Actual rate 97.697942517082
=====> Test::Metronome[73] Actual rate 98.7707258980831
=====> Test::Metronome[73] Actual rate 99.8434626078775
=====> Test::Metronome[73] Actual rate 99.5090989266317
=====> Test::Metronome[73] Actual rate 100.483952901939
=====> Test::Metronome[73] Actual rate 99.4844804910693
=====> Test::Metronome[73] Actual rate 100.512890634696
=====> Test::Metronome[73] Actual rate 99.4890883127012
=====> Test::Metronome[73] Actual rate 100.498025664435
=====> Test::Metronome[73] Actual rate 97.7505359760735
=====> Test::Metronome[79] Rates: count 81 minimum 56.3767918830855 maximum 100.939715008109 average 88.731389736976 sample_deviation 12.3364181140983
Test was not successful.
elliefm commented 7 years ago

test_maxforkrate(Cassandane::Cyrus::Master) and test_basic(Cassandane::Test::Metronome)

Yeah, we routinely get failures from the metronome tests on the cyrus.works infrastructure too. I'd say just disable these two, they seem to be highly dependent on system performance, which is useful if you're testing your own infrastructure, but makes no sense on shared build farm

Not sure what the login failures are about, but it looks like it could affect pretty much any random test (since most tests will do a login). I wonder if it's also a performance-related, maybe something in the login process is timing out too quickly?

jasontibbitts commented 6 years ago

Here's another random failure that cropped up. The VM running this test didn't seem to be particularly loaded so I'm not really sure what happened. I resubmitted the job and it went through, but of course that was on a completely different builder.

Run: 639, Failures: 1, Errors: 0
There was 1 failure:
1) test_basic_idled(Cassandane::Cyrus::Idle)
 Boolean assertion failed at /usr/share/perl5/vendor_perl/Test/Unit/Exception.pm line 13.
    Test::Unit::Exception::throw_new(Test::Unit::Failure=HASH(0xbe1e5b8), "-package", "Cassandane::Cyrus::Idle", "-file", "Cassandane/Cyrus/Idle.pm", "-line", 152, "-object", ...) called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 85
    Test::Unit::Assert::do_assertion(Cassandane::Cyrus::Idle=HASH(0xaff7728), Test::Unit::Assertion::Boolean=SCALAR(0xbe1e768), "Cassandane::Cyrus::Idle", "Cassandane/Cyrus/Idle.pm", 152) called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 19
    Test::Unit::Assert::assert(Cassandane::Cyrus::Idle=HASH(0xaff7728), undef) called at Cassandane/Cyrus/Idle.pm line 152
    Cassandane::Cyrus::Idle::common_basic(Cassandane::Cyrus::Idle=HASH(0xaff7728)) called at Cassandane/Cyrus/Idle.pm line 181
    Cassandane::Cyrus::Idle::test_basic_idled(Cassandane::Cyrus::Idle=HASH(0xaff7728)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
    [...framework calls elided...]
Annotations:
=====> Cyrus::TestCase[567] ---------- BEGIN test_basic_idled ----------
=====> Cyrus::TestCase[574] Calling test function
=====> Cyrus::Idle[175] Basic test of the IDLE command, idled started
=====> Instance[1004] start main instance for test test_basic_idled: basedir /builddir/build/BUILD/cyrus-imapd-3.0.4/cassandane/work/194331]4
=====> Instance[455] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.4-2.fc26.i386/usr/sbin
=====> Instance[455] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.4-2.fc26.i386/usr/sbin
=====> Instance[1505] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.4-2.fc26.i386/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.4/cassandane/work/194331]4/conf/imapd.conf"
=====> Instance[455] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.4-2.fc26.i386/usr/sbin
=====> Instance[455] Found binary idled in /builddir/build/BUILDROOT/cyrus-imapd-3.0.4-2.fc26.i386/usr/libexec/cyrus-imapd
=====> Instance[455] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.4-2.fc26.i386/usr/libexec/cyrus-imapd
=====> Instance[455] Found binary lmtpd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.4-2.fc26.i386/usr/libexec/cyrus-imapd
=====> Instance[916] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.4/cassandane/work/194331]4 as 8415
=====> Instance[1759] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.4/cassandane/work/194331]4/run/mux
=====> Instance[943] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.4/cassandane/work/194331]4 as 8420
=====> Instance[455] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.4-2.fc26.i386/usr/libexec/cyrus-imapd
=====> Instance[1505] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.4-2.fc26.i386/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.4/cassandane/work/194331]4/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.4/cassandane/work/194331]4/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.4/cassandane/work/194331]4/conf/cyrus.conf"
=====> Instance[868] _start_master: waiting for PID file
=====> Instance[871] _start_master: PID file present and correct
=====> Instance[883] _start_master: PID waiting for services
=====> Daemon[358] is_listening: service imap is listening on 127.0.0.1:9384
=====> Util::Wait[77] Waited 0.089642 sec for 127.0.0.1:9384 to be in LISTEN state
=====> Daemon[358] is_listening: service lmtp is listening on /builddir/build/BUILD/cyrus-imapd-3.0.4/cassandane/work/194331]4/conf/socket/lmtp
=====> Instance[894] _start_master: all services listening
=====> Instance[970] create user cassandane
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9384
=====> Instance[1774] authdaemon connection: admin testpw imap 
=====> Instance[1035] started main instance for test test_basic_idled: cyrus version 3.0.4-2.fc26 Fedora
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9384
=====> Instance[1774] authdaemon connection: cassandane testpw imap 
=====> Cyrus::Idle[151] The server should report the IDLE capability
=====> Cyrus::TestCase[681] Beginning tear_down
=====> Instance[1242] stop
=====> Instance[1204] _stop_pid: sending signal 15 to 8530
=====> Util::Wait[77] Waited 0.01011 sec for unknown condition
=====> Instance[919] killing saslauthd 8415
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 913.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 913.
=====> Instance[946] killing notifyd 8420
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 940.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 940.
=====> Instance[919] killing saslauthd 8415
=====> Instance[1270] Cleaning up basedir /builddir/build/BUILD/cyrus-imapd-3.0.4/cassandane/work/194331]4
=====> Cyrus::TestCase[726] ---------- END test_basic_idled ----------
=====> Daemon[387] checking for stray processes on ports: 9384
Test was not successful.
elliefm commented 6 years ago

test_replication_mailbox_new_enough

I've just re-read the log from this one, and it's another occurrence of "tar output dirname contains junk" issue:

=====> Instance[1501] Running: "tar" "-x" "-f" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane-2f8f3f4949e58bf20362c3cd8b1720f49002660d/data/old-mailboxes/version10.tar.gz" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.1/cassandane/work/155613\11/data/user/cassandane"

Are you still getting the intermittent login failure errors?

jasontibbitts commented 6 years ago

It does after all of the intervening time, Cassandane fixes and changes I've made to the packaging and the Cassandane config we're using, I don't think I'm seeing any intermittent failures. I've also just excluded a number of tests, but I think those were all due to consistent failures and not anything intermittent. So it might be best to just close this.

elliefm commented 6 years ago

No worries, thanks for all the reports :)