Odd characters in generated pathnames which cause unpackfile to fail

[jasontibbitts]

I'm seeing random failures of the Replication.replication_mailbox_too_old test. That test invokes tar to unpack some test data, but that fails with Perl exception: child process (binary tar pid 1955) exited with code 2. Looking through the log, I see:

Running: "tar" "-x" "-f" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane-2b355ec031b4fce0ea5105dd7ecabb2bbffbeff5/data/old-mailboxes/version9.tar.gz" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11/data/user/cassandane"

tar: /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\t/data/user/cassandane: Cannot open: No such file or directory
tar: Error is not recoverable: exiting now

So the big question is... how did a tab character get inserted into the directory name there? And why doesn't that happen consistently? Most of the time this test passes just fine. (Note that I'm assuming it's failed because of the tab character.)

The complete cassandane output (sorry for the length):

There was 1 error:
1) test_replication_mailbox_too_old(Cassandane::Cyrus::Replication)
 Perl exception: child process (binary tar pid 1955) exited with code 2
 at Cassandane/Instance.pm line 1505.
    Cassandane::Instance::__ANON__(HASH(0x5b3c3774), 2) called at Cassandane/Instance.pm line 1696
    Cassandane::Instance::_handle_wait_status(Cassandane::Instance=HASH(0x5a89cc04), 1955) called at Cassandane/Instance.pm line 1477
    Cassandane::Instance::reap_command(Cassandane::Instance=HASH(0x5a89cc04), 1955) called at Cassandane/Instance.pm line 1467
    Cassandane::Instance::run_command(Cassandane::Instance=HASH(0x5a89cc04), HASH(0x5b36c658), "tar", "-x", "-f", "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane-2b355ec031"..., "-C", "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/17341"...) called at Cassandane/Instance.pm line 1798
    Cassandane::Instance::unpackfile(Cassandane::Instance=HASH(0x5a89cc04), "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane-2b355ec031"..., "data/user/cassandane") called at Cassandane/Instance.pm line 2014
    Cassandane::Instance::install_old_mailbox(Cassandane::Instance=HASH(0x5a89cc04), "cassandane", 9) called at Cassandane/Cyrus/Replication.pm line 732
    Cassandane::Cyrus::Replication::test_replication_mailbox_too_old(Cassandane::Cyrus::Replication=HASH(0x5ad520b8)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
    [...framework calls elided...]
Annotations:
=====> Cyrus::TestCase[565] ---------- BEGIN test_replication_mailbox_too_old ----------
=====> Cyrus::TestCase[158] Magic word replication in name wants replica = 1
=====> Instance[1074] start main instance for test test_replication_mailbox_too_old: basedir /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10
=====> Instance[1057] started smtpd as 1485
2018/04/03-17:34:26 Cassandane::Net::SMTPServer (type Net::Server::PreForkSimple) starting! pid(1485)
Resolved [localhost]:9642 to [::1]:9642, IPv6
Resolved [localhost]:9642 to [127.0.0.1]:9642, IPv4
=====> Instance[474] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/sbin
=====> Instance[474] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/sbin
=====> Instance[1579] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10/conf/imapd.conf"
Binding to TCP port 9642 on host ::1 with IPv6
Binding to TCP port 9642 on host 127.0.0.1 with IPv4
Group Not Defined.  Defaulting to EGID '425 425'
User Not Defined.  Defaulting to EUID '1000'
=====> Instance[1655] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515266',
    '515266'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515266',
    '515266'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
=====> Instance[474] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/sbin
=====> Instance[474] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/libexec/cyrus-imapd
=====> Instance[945] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10 as 1497
=====> Instance[1842] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10/run/mux
=====> Instance[972] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10 as 1498
chmod: cannot access '/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/17341010/run/mux': No such file or directory
=====> Instance[888] _start_master: logging to /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10/conf/master.log
=====> Instance[474] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/libexec/cyrus-imapd
=====> Instance[1579] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10/conf/cyrus.conf" "-L" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10/conf/master.log"
=====> Instance[1655] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515266',
    '515266'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515266',
    '515266'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
=====> Instance[897] _start_master: waiting for PID file
=====> Instance[900] _start_master: PID file present and correct
=====> Instance[912] _start_master: PID waiting for services
=====> Daemon[356] is_listening: service imap is listening on 127.0.0.1:9643
=====> Util::Wait[75] Waited 0.116834 sec for 127.0.0.1:9643 to be in LISTEN state
=====> Instance[923] _start_master: all services listening
=====> Instance[999] create user cassandane
=====> Util::Socket[61] create_client_socket INET host=127.0.0.1 port=9643
C: 1 capability
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] buildhw-07.phx2.fedoraproject.org Cyrus IMAP 3.0.5-11.fc29 Fedora server ready
S: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY AUTH=PLAIN AUTH=LOGIN SASL-IR COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE
S: 1 OK Completed
C: 2 login admin "testpw"
=====> Instance[1857] authdaemon connection: admin testpw imap 
S: 2 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY LOGINDISABLED COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] User logged in SESSIONID=<173410\10-1577-1522776867-1-10315761525690285861>
C: 3 create user.cassandane
S: 3 OK Completed
C: 4 setacl user.cassandane admin lrswipkxtecdan
S: 4 OK Completed
C: 5 setacl user.cassandane cassandane lrswipkxtecdn
S: 5 OK Completed
C: 6 setacl user.cassandane anyone p
S: 6 OK Completed
A: is_open test
A: is_open test received timeout, still open
C: 7 logout
S: * BYE LOGOUT received
S: 7 OK Completed
A: Release socket, fileno=65
=====> Instance[1109] started main instance for test test_replication_mailbox_too_old: cyrus version 3.0.5-11.fc29 Fedora
=====> Instance[1074] start replica instance for test test_replication_mailbox_too_old: basedir /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11
=====> Instance[1057] started smtpd as 1706
2018/04/03-17:34:27 Cassandane::Net::SMTPServer (type Net::Server::PreForkSimple) starting! pid(1706)
Resolved [localhost]:9644 to [::1]:9644, IPv6
Resolved [localhost]:9644 to [127.0.0.1]:9644, IPv4
=====> Instance[474] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/sbin
=====> Instance[474] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/sbin
=====> Instance[1579] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11/conf/imapd.conf"
Binding to TCP port 9644 on host ::1 with IPv6
Binding to TCP port 9644 on host 127.0.0.1 with IPv4
Group Not Defined.  Defaulting to EGID '425 425'
User Not Defined.  Defaulting to EUID '1000'
=====> Instance[1655] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515266',
    '515266'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515266',
    '515266'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
=====> Instance[474] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/sbin
=====> Instance[474] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/libexec/cyrus-imapd
=====> Instance[474] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/libexec/cyrus-imapd
=====> Instance[945] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11 as 1746
=====> Instance[1842] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11/run/mux
=====> Instance[972] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11 as 1748
chmod: cannot access '/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/17341011/run/mux': No such file or directory
=====> Instance[888] _start_master: logging to /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11/conf/master.log
=====> Instance[474] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/libexec/cyrus-imapd
=====> Instance[1579] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11/conf/cyrus.conf" "-L" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11/conf/master.log"
=====> Instance[1655] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515266',
    '515266'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515266',
    '515266'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
=====> Instance[897] _start_master: waiting for PID file
=====> Instance[900] _start_master: PID file present and correct
=====> Instance[912] _start_master: PID waiting for services
=====> Daemon[356] is_listening: service sync is listening on 127.0.0.1:9641
=====> Util::Wait[75] Waited 0.115266 sec for 127.0.0.1:9641 to be in LISTEN state
=====> Daemon[356] is_listening: service imap is listening on 127.0.0.1:9645
=====> Instance[923] _start_master: all services listening
=====> Instance[1109] started replica instance for test test_replication_mailbox_too_old: cyrus version 3.0.5-11.fc29 Fedora
=====> Cyrus::TestCase[940] running replication
=====> Instance[474] Found binary sync_client in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/sbin
=====> Instance[1579] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/sbin/sync_client" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10/conf/imapd.conf" "-v" "-v" "-o" "-S" "127.0.0.1" "-u" "cassandane"
=====> Instance[1655] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515266',
    '515266'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515266',
    '515266'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
173410\10/sync_client[1871]: SQL backend defaulting to engine 'pgsql'
=====> Instance[1857] authdaemon connection: repluser replpass imap 
173410\10/sync_client[1871]: imap_sasl_parsesuccess(): input is: A01 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY LOGINDISABLED COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] Success (no protection) SESSIONID=<173410\11-1879-1522776867-1-12521548255055552788>
173410\10/sync_client[1871]: imap_sasl_parsesuccess(): found capability string: [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY LOGINDISABLED COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE]
USER cassandane
>1522776867>S0 SYNCGET USER cassandane
<1522776867<S0 OK success
MAILBOX user.cassandane
>1522776867>S1 SYNCAPPLY MAILBOX %(UNIQUEID 8060a1db-dd98-4262-8ff8-1ad5d7198e20 MBOXNAME user.cassandane SYNC_CRC 0 SYNC_CRC_ANNOT 0 LAST_UID 0 HIGHESTMODSEQ 3 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 UIDVALIDITY 1522776868 PARTITION default ACL "cassandane    lrswipkxtecdan  admin   lrswipkxtecdan  anyone  p   " OPTIONS P RECORD ())
<1522776867<S1 OK success
>1522776867>Q01 LOGOUT
<1522776868<* BYE LOGOUT received
Q01 OK Completed
=====> Cyrus::TestCase[572] Calling test function
=====> Instance[2010] installing version 9 mailbox for user cassandane
=====> Instance[1579] Running: "tar" "-x" "-f" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane-2b355ec031b4fce0ea5105dd7ecabb2bbffbeff5/data/old-mailboxes/version9.tar.gz" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11/data/user/cassandane"
=====> Instance[1655] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515266',
    '515266'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515266',
    '515266'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
tar: /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\t/data/user/cassandane: Cannot open: No such file or directory
tar: Error is not recoverable: exiting now
=====> Cyrus::TestCase[679] Beginning tear_down
=====> Instance[1316] stop
=====> Instance[1278] _stop_pid: sending signal 15 to 1525
=====> Util::Wait[75] Waited 0.025149 sec for unknown condition
=====> Instance[1060] killing smtpd 1485
2018/04/03-17:34:28 Server closing!
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/lib/perl5/IO/Select.pm line 120.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/lib/perl5/IO/Select.pm line 120.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
=====> Instance[948] killing saslauthd 1497
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 942.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 942.
=====> Instance[1060] killing smtpd 1485
=====> Instance[975] killing notifyd 1498
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 969.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 969.
=====> Instance[1060] killing smtpd 1485
=====> Instance[948] killing saslauthd 1497
=====> Instance[1316] stop
=====> Instance[1278] _stop_pid: sending signal 15 to 1784
=====> Util::Wait[75] Waited 0.010111 sec for unknown condition
=====> Instance[1060] killing smtpd 1706
2018/04/03-17:34:28 Server closing!
=====> Instance[948] killing saslauthd 1746
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/lib/perl5/IO/Select.pm line 120.
=====> Instance[1060] killing smtpd 1485
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/lib/perl5/IO/Select.pm line 120.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 942.
=====> Instance[948] killing saslauthd 1497
=====> Instance[975] killing notifyd 1498
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 942.
=====> Instance[1060] killing smtpd 1706
=====> Instance[1060] killing smtpd 1485
=====> Instance[1060] killing smtpd 1485
=====> Instance[948] killing saslauthd 1497
=====> Instance[975] killing notifyd 1498
=====> Instance[948] killing saslauthd 1497
=====> Instance[975] killing notifyd 1498
=====> Instance[975] killing notifyd 1748
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 969.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 969.
=====> Instance[1060] killing smtpd 1706
=====> Instance[948] killing saslauthd 1746
=====> Instance[1060] killing smtpd 1485
=====> Instance[948] killing saslauthd 1497
=====> Instance[975] killing notifyd 1498
=====> Cyrus::TestCase[724] ---------- END test_replication_mailbox_too_old ----------
=====> Daemon[385] checking for stray processes on ports: 9641 9642 9643 9644 9645
Test was not successful.

[jasontibbitts]

I wanted to add that since I started following the Cassandane more closely (currently I'm running 2b355ec031b4fce0ea5105dd7ecabb2bbffbeff5 which is HEAD at the time I write this) I've had a lot of problems consistently getting a successful run on our buildsystem. It of course works perfectly on my fast desktop, but our builders aren't uniformly fast. The failures seem to be in random tests but mostly caused by something already listening on some random port, but this one failure seemed to have an odd cause with the failing tar call and the tab character.

[elliefm]

Wow this is really weird

It looks like the tab character is coming from the Instance object's {basedir} attribute, this is how the destination (-C) path is generated (Cassandane/Instance.pm, sub unpackfile):

        # unpack relatively to base directory
        $dst = $self->{basedir} . '/' . $dst;

(The $dst that is passed in here is "data/user/$user", i.e. the "data/user/cassandane" at the end of the path.)

I'm looking through the log and seeing other, weirdness, look at this:

=====> Instance[1074] start main instance for test test_replication_mailbox_too_old: basedir /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10
[...]
=====> Instance[1579] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-11.fc29.i386/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\10/conf/imapd.conf"
[...]
=====> Instance[1074] start replica instance for test test_replication_mailbox_too_old: basedir /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/173410\11

So it looks like these broken basedirs are turning up early, it's not some weird data corruption happening way down the track...

Will have a dig and report back.

[elliefm]

For comparison, here's what a basedir looks like on my system:

=====> Instance[1074] start main instance for test test_replication_mailbox_too_old: basedir /dev/shm/cass/022145A1

Note that the random component is 8 hex chars, whereas yours are 6 hex chars and some junk? I wonder if the build system is hitting a different "generate random directory" code path from our desktops, and the bug is in that codepath somewhere.

I can see how junk bytes in working directory paths would create all sorts of havoc... might explain all the other random failures too.

[elliefm]

Can you add this patch, and report back what it logs?

diff --git a/Cassandane/Instance.pm b/Cassandane/Instance.pm
index 6c6daf7..91f1ca2 100644
--- a/Cassandane/Instance.pm
+++ b/Cassandane/Instance.pm
@@ -274,6 +274,7 @@ sub _make_unique_instance_info
        die "Invalid TEST_UNIT_WORKER_ID - code not run in Worker context"
            if (defined($workerid) && $workerid eq 'invalid');
        $stamp .= chr(64 + $workerid) if defined $workerid;
+       xlog "workerid: $workerid, stamp: $stamp"
     }

     my $rootdir = _rootdir();
@@ -285,6 +286,7 @@ sub _make_unique_instance_info
        $name = $stamp . $next_unique;
        $next_unique++;
        $basedir = "$rootdir/$name";
+       xlog "name: $name, basedir: $basedir";
        last if mkdir($basedir);
        die "Cannot create $basedir: $!" if ($! != EEXIST);
     }

On my system, I get lines like this very early in the output:

=====> Instance[277] workerid: 1, stamp: 023401A
=====> Instance[289] name: 023401A1, basedir: /dev/shm/cass/023401A1

[elliefm]

Oh also, that's not a hex number, as it turns out. It's 6 decimal digits, followed by a workerid encoded as an alphabetic character (A=1, B=2, etc), followed by counter that starts at 1.

Looks like the conversion from a workerid is to a character is misbehaving on the buildsystem? Weird. I wonder what locale the buildsystem is in, and whether that's causing the chr(64 + $workerid) to do something unexpected?

[elliefm]

Not sure if this is relevant either, but for comparison, I have:

$perl --version

This is perl 5, version 24, subversion 1 (v5.24.1) built for x86_64-linux-gnu-thread-multi
(with 75 registered patches, see perl -V for more detail)

[elliefm]

Ohhhhh how many jobs/workers does the buildsystem run? I guess if it runs a large enough number, then chr(64 + $workerid) might overflow to a low-value such as 10 or 11...

This might suggest a practical upper bound of 26 for the testrunner -j argument and maxworkers cassandane.ini setting...

[jasontibbitts]

I wish I had been around last night to talk about this. If you want you can see the complete package build log at https://kojipkgs.fedoraproject.org//work/tasks/4467/26124467/build.log, but it will expire in twelve days.

In this case, though Cassandane was run as:

./testrunner.pl -j6 -v -f pretty '!Metronome' '!Cassandane::Test::Core' '!Master.sighup_recycling' '!SearchFuzzy.cjk_words' '!Admin.imap_admins' '!ImapTest' '!Caldav.changes_remove' '!CaldavAlarm.override_multiuser' '!Annotator.annotator_callout_disabled' '!CaldavAlarm.simple_multiuser_sametime' '!CaldavAlarm.simple_multiuser' '!Carddav.sharing_contactpaths' '!Info.info_lint_junk' '!Info.info_lint' '!Metadata.set_specialuse_twice' '!SearchFuzzy.search_subjectsnippet'

So only six workers, which shouldn't overflow. On my desktop, it runs with -j20 and doesn't seem to run into any problems with that. The Perl version used here was 5.26.2 RC1. And I guess there could be some problem with using a release candidate of Perl, but in that case I'd think it would be repeatable.

I will patch in that bit but unfortunately I can't really repeat this so I'll just leave it in there in case I managed to catch this again.

And I did manage to work out why we had so many random Cassandane failures. It seems that it will fail if anything on the machine happens to be using one of the many ports it wants. Our builds aren't (yet) done with full network isolation so some services living in the mid 9000 range would mess with the builds. I patched things to use a base port of 19100 and was able to get some clean builds. I guess I could file an RFE asking for it to be configurable but I'm not sure it's worth it.

[elliefm]

I guess I could file an RFE asking for it to be configurable but I'm not sure it's worth it.

On the other hand, it seems like it wouldn't be that hard to make it configurable, and if it's causing problems for you it will cause problems for someone else, so we might as well. :)

I had a skim through that package build log, but nothing in particular was jumping out at me. Hopefully the extra logging will be enough to be useful next time it gets weird.

[elliefm]

Actually I'd be very interested to see any build log that has that patch in it (even if its errors aren't related to the weird \11 thing). Since the worker id's and stuff will be logged for every test, I might still get useful information even from just a bunch of unrelated failures.

[jasontibbitts]

I just had a similar failure in a different test; this time it's Bug3463.thread_crash, and also involving a call to tar to unpack into a directory containing "odd" characters.. This failure was also on the i686 architecture; I don't know yet if that is relevant. I did have the additional logging patch included so you can see things like:

=====> Instance[277] workerid: 28, stamp: 182357\
=====> Instance[289] name: 182357\1, basedir: /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1

The complete log will be at https://kojipkgs.fedoraproject.org//work/tasks/1190/26311190/build.log, but only for a couple more weeks. Here is the Cassandane output for the failed test; you can see \1 in a number of places.

There was 1 failure:
1) test_thread_crash(Cassandane::Cyrus::Bug3463)
 Boolean assertion failed at /usr/share/perl5/vendor_perl/Test/Unit/Exception.pm line 13.
    Test::Unit::Exception::throw_new(Test::Unit::Failure=HASH(0x5ac147f8), "-package", "Cassandane::Cyrus::Bug3463", "-file", "Cassandane/Cyrus/Bug3463.pm", "-line", 86, "-object", ...) called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 85
    Test::Unit::Assert::do_assertion(Cassandane::Cyrus::Bug3463=HASH(0x59a2b724), Test::Unit::Assertion::Boolean=SCALAR(0x5a9ede38), "Cassandane::Cyrus::Bug3463", "Cassandane/Cyrus/Bug3463.pm", 86) called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 19
    Test::Unit::Assert::assert(Cassandane::Cyrus::Bug3463=HASH(0x59a2b724), "") called at Cassandane/Cyrus/Bug3463.pm line 86
    Cassandane::Cyrus::Bug3463::test_thread_crash(Cassandane::Cyrus::Bug3463=HASH(0x59a2b724)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
    [...framework calls elided...]
Annotations:
=====> Cyrus::TestCase[565] ---------- BEGIN test_thread_crash ----------
=====> Instance[277] workerid: 28, stamp: 182357\
=====> Instance[289] name: 182357\1, basedir: /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1
=====> Instance[1076] start main instance for test test_thread_crash: basedir /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1
=====> Instance[1059] started smtpd as 41058
=====> Instance[476] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.i386/usr/sbin
=====> Instance[476] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.i386/usr/sbin
=====> Instance[1595] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.i386/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1/conf/imapd.conf"
2018/04/11-18:23:57 Cassandane::Net::SMTPServer (type Net::Server::PreForkSimple) starting! pid(41058)
Resolved [localhost]:19640 to [::1]:19640, IPv6
Resolved [localhost]:19640 to [127.0.0.1]:19640, IPv4
Binding to TCP port 19640 on host ::1 with IPv6
Binding to TCP port 19640 on host 127.0.0.1 with IPv4
Group Not Defined.  Defaulting to EGID '425 425'
User Not Defined.  Defaulting to EUID '1000'
=====> Instance[476] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.i386/usr/sbin
=====> Instance[476] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.i386/usr/libexec/cyrus-imapd
=====> Instance[947] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1 as 41243
=====> Instance[974] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1 as 41254
=====> Instance[1858] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1/run/mux
chmod: cannot access '/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1823571/run/mux': No such file or directory
=====> Instance[890] _start_master: logging to /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1/conf/master.log
=====> Instance[476] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.i386/usr/libexec/cyrus-imapd
=====> Instance[1595] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.i386/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1/conf/cyrus.conf" "-L" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/182357\1/conf/master.log"
=====> Instance[899] _start_master: waiting for PID file
=====> Instance[902] _start_master: PID file present and correct
=====> Instance[914] _start_master: PID waiting for services
=====> Daemon[356] is_listening: service imap is listening on 127.0.0.1:19641
=====> Util::Wait[75] Waited 0.156496 sec for 127.0.0.1:19641 to be in LISTEN state
=====> Instance[925] _start_master: all services listening
=====> Instance[1001] create user cassandane
=====> Util::Socket[61] create_client_socket INET host=127.0.0.1 port=19641
C: 1 capability
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] buildhw-02.phx2.fedoraproject.org Cyrus IMAP 3.0.5-12.fc29 Fedora server ready
S: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY AUTH=PLAIN AUTH=LOGIN SASL-IR COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE
S: 1 OK Completed
C: 2 login admin "testpw"
=====> Instance[1873] authdaemon connection: admin testpw imap 
S: 2 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY LOGINDISABLED COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] User logged in SESSIONID=<182357\1-41803-1523471037-1-3197316800867274181>
C: 3 create user.cassandane
S: 3 OK Completed
C: 4 setacl user.cassandane admin lrswipkxtecdan
S: 4 OK Completed
C: 5 setacl user.cassandane cassandane lrswipkxtecdn
S: 5 OK Completed
C: 6 setacl user.cassandane anyone p
S: 6 OK Completed
A: is_open test
A: is_open test received timeout, still open
C: 7 logout
S: * BYE LOGOUT received
S: 7 OK Completed
A: Release socket, fileno=63
=====> Instance[1111] started main instance for test test_thread_crash: cyrus version 3.0.5-12.fc29 Fedora
=====> Cyrus::TestCase[572] Calling test function
=====> Util::Socket[61] create_client_socket INET host=127.0.0.1 port=19641
C: 1 capability
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] buildhw-02.phx2.fedoraproject.org Cyrus IMAP 3.0.5-12.fc29 Fedora server ready
S: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY AUTH=PLAIN AUTH=LOGIN SASL-IR COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE
S: 1 OK Completed
C: 2 login cassandane "testpw"
=====> Instance[1873] authdaemon connection: cassandane testpw imap 
S: 2 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY LOGINDISABLED COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] User logged in SESSIONID=<182357\1-41803-1523471037-2-15264165361698915360>
C: 3 create INBOX.problem-eposter
S: 3 OK Completed
tar: /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1823571/data/user/cassandane: Cannot open: No such file or directory
tar: Error is not recoverable: exiting now
C: 4 select "INBOX.problem-eposter"
S: * 0 EXISTS
S: * 0 RECENT
S: * FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
S: * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)] Ok
S: * OK [UIDVALIDITY 1523471038] Ok
S: * OK [UIDNEXT 1] Ok
S: * OK [HIGHESTMODSEQ 1] Ok
S: * OK [URLMECH INTERNAL] Ok
S: * OK [ANNOTATIONS 65536] Ok
S: 4 OK [READ-WRITE] Completed
C: 5 thread REFERENCES utf-8 ALL
S: * THREAD
S: 5 OK Completed (0 msgs in 0.000 secs)
=====> Cyrus::TestCase[679] Beginning tear_down
C: 6 logout
S: * BYE LOGOUT received
S: 6 OK Completed
A: Release socket, fileno=63
=====> Instance[1318] stop
=====> Instance[1280] _stop_pid: sending signal 15 to 41506
=====> Util::Wait[75] Waited 0.010109 sec for unknown condition
=====> Instance[1062] killing smtpd 41058
2018/04/11-18:23:57 Server closing!
=====> Instance[950] killing saslauthd 41243
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/lib/perl5/IO/Select.pm line 120.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/lib/perl5/IO/Select.pm line 120.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 944.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 944.
=====> Instance[1062] killing smtpd 41058
=====> Instance[977] killing notifyd 41254
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 971.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 971.
=====> Instance[1062] killing smtpd 41058
=====> Instance[950] killing saslauthd 41243
=====> Cyrus::TestCase[724] ---------- END test_thread_crash ----------
=====> Daemon[385] checking for stray processes on ports: 19640 19641
Test was not successful.

[jasontibbitts]

I hate to spam, but just in case it helps, here's another instance. This time it's on an x86_64 builder (so it's not a 32-bit problem) and it's in Fedora 28 beta (which is in the last stages of being firmed up for release, so, for example, it's running a released version of perl {5.26.1}). The complete build info is available from https://koji.fedoraproject.org/koji/taskinfo?taskID=26203962 for about another nine days. Unfortunately the Fedora 28 branch doesn't have that extra debugging patch in it.

There was 1 error:
1) test_replication_mailbox_too_old(Cassandane::Cyrus::Replication)
 Perl exception: child process (binary tar pid 7299) exited with code 2
 at Cassandane/Instance.pm line 1499.
    Cassandane::Instance::__ANON__(HASH(0x558bbac5b338), 2) called at Cassandane/Instance.pm line 1690
    Cassandane::Instance::_handle_wait_status(Cassandane::Instance=HASH(0x558bbabc67e8), 7299) called at Cassandane/Instance.pm line 1471
    Cassandane::Instance::reap_command(Cassandane::Instance=HASH(0x558bbabc67e8), 7299) called at Cassandane/Instance.pm line 1461
    Cassandane::Instance::run_command(Cassandane::Instance=HASH(0x558bbabc67e8), HASH(0x558bbac5b8a0), "tar", "-x", "-f", "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane-6bd697c479"..., "-C", "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/05311"...) called at Cassandane/Instance.pm line 1792
    Cassandane::Instance::unpackfile(Cassandane::Instance=HASH(0x558bbabc67e8), "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane-6bd697c479"..., "data/user/cassandane") called at Cassandane/Instance.pm line 2008
    Cassandane::Instance::install_old_mailbox(Cassandane::Instance=HASH(0x558bbabc67e8), "cassandane", 9) called at Cassandane/Cyrus/Replication.pm line 732
    Cassandane::Cyrus::Replication::test_replication_mailbox_too_old(Cassandane::Cyrus::Replication=HASH(0x558bba162620)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
    [...framework calls elided...]
Annotations:
=====> Cyrus::TestCase[565] ---------- BEGIN test_replication_mailbox_too_old ----------
=====> Cyrus::TestCase[158] Magic word replication in name wants replica = 1
=====> Instance[1068] start main instance for test test_replication_mailbox_too_old: basedir /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\12
=====> Instance[1051] started smtpd as 6836
2018/04/07-05:31:34 Cassandane::Net::SMTPServer (type Net::Server::PreForkSimple) starting! pid(6836)
Resolved [localhost]:9649 to [::1]:9649, IPv6
Resolved [localhost]:9649 to [127.0.0.1]:9649, IPv4
Binding to TCP port 9649 on host ::1 with IPv6
Binding to TCP port 9649 on host 127.0.0.1 with IPv4
Group Not Defined.  Defaulting to EGID '425 425'
User Not Defined.  Defaulting to EUID '1000'
=====> Instance[474] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin
=====> Instance[474] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin
=====> Instance[1573] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\12/conf/imapd.conf"
=====> Instance[1649] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515267',
    '515267'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515267',
    '515267'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
=====> Instance[474] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin
=====> Instance[474] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd
=====> Instance[939] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\12 as 6863
=====> Instance[1836] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\12/run/mux
=====> Instance[966] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\12 as 6869
chmod: cannot access '/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/05311612/run/mux': No such file or directory
=====> Instance[882] _start_master: logging to /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\12/conf/master.log
=====> Instance[474] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd
=====> Instance[1573] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\12/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\12/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\12/conf/cyrus.conf" "-L" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\12/conf/master.log"
=====> Instance[1649] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515267',
    '515267'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515267',
    '515267'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
=====> Instance[891] _start_master: waiting for PID file
=====> Instance[894] _start_master: PID file present and correct
=====> Instance[906] _start_master: PID waiting for services
=====> Daemon[356] is_listening: service imap is listening on 127.0.0.1:9650
=====> Util::Wait[75] Waited 0.133983 sec for 127.0.0.1:9650 to be in LISTEN state
=====> Instance[917] _start_master: all services listening
=====> Instance[993] create user cassandane
=====> Util::Socket[61] create_client_socket INET host=127.0.0.1 port=9650
C: 1 capability
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] buildhw-02.phx2.fedoraproject.org Cyrus IMAP 3.0.5-7.fc28 Fedora server ready
S: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY AUTH=PLAIN AUTH=LOGIN SASL-IR COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE
S: 1 OK Completed
C: 2 login admin "testpw"
=====> Instance[1851] authdaemon connection: admin testpw imap 
S: 2 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY LOGINDISABLED COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] User logged in SESSIONID=<053116\12-6967-1523079095-1-8184574309607254356>
C: 3 create user.cassandane
S: 3 OK Completed
C: 4 setacl user.cassandane admin lrswipkxtecdan
S: 4 OK Completed
C: 5 setacl user.cassandane cassandane lrswipkxtecdn
S: 5 OK Completed
C: 6 setacl user.cassandane anyone p
S: 6 OK Completed
A: is_open test
A: is_open test received timeout, still open
C: 7 logout
S: * BYE LOGOUT received
S: 7 OK Completed
A: Release socket, fileno=65
=====> Instance[1103] started main instance for test test_replication_mailbox_too_old: cyrus version 3.0.5-7.fc28 Fedora
=====> Instance[1068] start replica instance for test test_replication_mailbox_too_old: basedir /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\13
=====> Instance[1051] started smtpd as 7058
2018/04/07-05:31:35 Cassandane::Net::SMTPServer (type Net::Server::PreForkSimple) starting! pid(7058)
Resolved [localhost]:9651 to [::1]:9651, IPv6
Resolved [localhost]:9651 to [127.0.0.1]:9651, IPv4
Binding to TCP port 9651 on host ::1 with IPv6
Binding to TCP port 9651 on host 127.0.0.1 with IPv4
Group Not Defined.  Defaulting to EGID '425 425'
User Not Defined.  Defaulting to EUID '1000'
=====> Instance[474] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin
=====> Instance[474] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin
=====> Instance[1573] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\13/conf/imapd.conf"
=====> Instance[1649] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515267',
    '515267'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515267',
    '515267'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
=====> Instance[474] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin
=====> Instance[474] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd
=====> Instance[474] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd
=====> Instance[939] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\13 as 7091
=====> Instance[1836] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\13/run/mux
=====> Instance[966] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\13 as 7099
chmod: cannot access '/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/05311613/run/mux': No such file or directory
=====> Instance[882] _start_master: logging to /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\13/conf/master.log
=====> Instance[474] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd
=====> Instance[1573] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\13/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\13/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\13/conf/cyrus.conf" "-L" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\13/conf/master.log"
=====> Instance[1649] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515267',
    '515267'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515267',
    '515267'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
=====> Instance[891] _start_master: waiting for PID file
=====> Instance[894] _start_master: PID file present and correct
=====> Instance[906] _start_master: PID waiting for services
=====> Daemon[356] is_listening: service sync is listening on 127.0.0.1:9648
=====> Util::Wait[75] Waited 0.104297 sec for 127.0.0.1:9648 to be in LISTEN state
=====> Daemon[356] is_listening: service imap is listening on 127.0.0.1:9652
=====> Instance[917] _start_master: all services listening
=====> Instance[1103] started replica instance for test test_replication_mailbox_too_old: cyrus version 3.0.5-7.fc28 Fedora
=====> Cyrus::TestCase[940] running replication
=====> Instance[474] Found binary sync_client in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin
=====> Instance[1573] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin/sync_client" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\12/conf/imapd.conf" "-v" "-v" "-o" "-S" "127.0.0.1" "-u" "cassandane"
=====> Instance[1649] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515267',
    '515267'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515267',
    '515267'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
053116\12/sync_client[7231]: SQL backend defaulting to engine 'pgsql'
=====> Instance[1851] authdaemon connection: repluser replpass imap 
053116\12/sync_client[7231]: imap_sasl_parsesuccess(): input is: A01 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY LOGINDISABLED COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] Success (no protection) SESSIONID=<053116\13-7245-1523079096-1-512531979231760493>
053116\12/sync_client[7231]: imap_sasl_parsesuccess(): found capability string: [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY LOGINDISABLED COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE]
USER cassandane
>1523079096>S0 SYNCGET USER cassandane
<1523079096<S0 OK success
MAILBOX user.cassandane
>1523079096>S1 SYNCAPPLY MAILBOX %(UNIQUEID 4831ab09-b61f-4954-8ed6-aa58ac853445 MBOXNAME user.cassandane SYNC_CRC 0 SYNC_CRC_ANNOT 0 LAST_UID 0 HIGHESTMODSEQ 3 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 UIDVALIDITY 1523079096 PARTITION default ACL "cassandane    lrswipkxtecdan  admin   lrswipkxtecdan  anyone  p   " OPTIONS P RECORD ())
<1523079096<S1 OK success
>1523079096>Q01 LOGOUT
<1523079096<* BYE LOGOUT received
Q01 OK Completed
=====> Cyrus::TestCase[572] Calling test function
=====> Instance[2004] installing version 9 mailbox for user cassandane
=====> Instance[1573] Running: "tar" "-x" "-f" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane-6bd697c4799cf3f5eed0d89fcc7a365a9ff93680/data/old-mailboxes/version9.tar.gz" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\13/data/user/cassandane"
=====> Instance[1649] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515267',
    '515267'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515267',
    '515267'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
tar: /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116\v/data/user/cassandane: Cannot open: No such file or directory
tar: Error is not recoverable: exiting now
=====> Cyrus::TestCase[679] Beginning tear_down
=====> Instance[1310] stop
=====> Instance[1272] _stop_pid: sending signal 15 to 6896
=====> Util::Wait[75] Waited 0.010114 sec for unknown condition
=====> Instance[1054] killing smtpd 6836
2018/04/07-05:31:36 Server closing!
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/lib64/perl5/IO/Select.pm line 120.
=====> Instance[942] killing saslauthd 6863
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/lib64/perl5/IO/Select.pm line 120.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 936.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 936.
=====> Instance[1054] killing smtpd 6836
=====> Instance[969] killing notifyd 6869
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 963.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 963.
=====> Instance[1054] killing smtpd 6836
=====> Instance[942] killing saslauthd 6863
=====> Instance[1310] stop
=====> Instance[1272] _stop_pid: sending signal 15 to 7160
=====> Util::Wait[75] Waited 0.025174 sec for unknown condition
=====> Instance[1054] killing smtpd 7058
2018/04/07-05:31:36 Server closing!
=====> Instance[942] killing saslauthd 7091
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/lib64/perl5/IO/Select.pm line 120.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/lib64/perl5/IO/Select.pm line 120.
=====> Instance[1054] killing smtpd 6836
=====> Instance[942] killing saslauthd 6863
=====> Instance[969] killing notifyd 6869
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
=====> Instance[1054] killing smtpd 6836
=====> Instance[942] killing saslauthd 6863
=====> Instance[969] killing notifyd 6869
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 936.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 936.
=====> Instance[1054] killing smtpd 7058
=====> Instance[1054] killing smtpd 6836
=====> Instance[942] killing saslauthd 6863
=====> Instance[969] killing notifyd 6869
=====> Instance[969] killing notifyd 7099
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 963.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 963.
=====> Instance[1054] killing smtpd 7058
=====> Instance[942] killing saslauthd 7091
=====> Instance[1054] killing smtpd 6836
=====> Instance[942] killing saslauthd 6863
=====> Instance[969] killing notifyd 6869
=====> Cyrus::TestCase[724] ---------- END test_replication_mailbox_too_old ----------
=====> Daemon[385] checking for stray processes on ports: 9648 9649 9650 9651 9652
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(0x558bbabc7888), "-package", "Cassandane::Cyrus::Idle", "-file", "Cassandane/Cyrus/Idle.pm", "-line", 155, "-object", ...) called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 85
    Test::Unit::Assert::do_assertion(Cassandane::Cyrus::Idle=HASH(0x558bb8e4c278), Test::Unit::Assertion::Boolean=SCALAR(0x558bbabc6aa0), "Cassandane::Cyrus::Idle", "Cassandane/Cyrus/Idle.pm", 155) called at /usr/share/perl5/vendor_perl/Test/Unit/Assert.pm line 19
    Test::Unit::Assert::assert(Cassandane::Cyrus::Idle=HASH(0x558bb8e4c278), undef) called at Cassandane/Cyrus/Idle.pm line 155
    Cassandane::Cyrus::Idle::common_basic(Cassandane::Cyrus::Idle=HASH(0x558bb8e4c278)) called at Cassandane/Cyrus/Idle.pm line 184
    Cassandane::Cyrus::Idle::test_basic_idled(Cassandane::Cyrus::Idle=HASH(0x558bb8e4c278)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
    [...framework calls elided...]
Annotations:
=====> Cyrus::TestCase[565] ---------- BEGIN test_basic_idled ----------
=====> Cyrus::TestCase[572] Calling test function
=====> Cyrus::Idle[178] Basic test of the IDLE command, idled started
=====> Instance[1068] start main instance for test test_basic_idled: basedir /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5
=====> Instance[1051] started smtpd as 953
=====> Instance[474] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin
=====> Instance[474] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin
=====> Instance[1573] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5/conf/imapd.conf"
2018/04/07-05:31:22 Cassandane::Net::SMTPServer (type Net::Server::PreForkSimple) starting! pid(953)
Resolved [localhost]:9670 to [::1]:9670, IPv6
Resolved [localhost]:9670 to [127.0.0.1]:9670, IPv4
=====> Instance[1649] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515267',
    '515267'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515267',
    '515267'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
Binding to TCP port 9670 on host ::1 with IPv6
Binding to TCP port 9670 on host 127.0.0.1 with IPv4
Group Not Defined.  Defaulting to EGID '425 425'
User Not Defined.  Defaulting to EUID '1000'
=====> Instance[474] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/sbin
=====> Instance[474] Found binary idled in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd
=====> Instance[474] Found binary lmtpd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd
=====> Instance[474] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd
=====> Instance[939] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5 as 991
=====> Instance[966] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5 as 996
=====> Instance[1836] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5/run/mux
=====> Instance[882] _start_master: logging to /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5/conf/master.log
=====> Instance[474] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd
=====> Instance[1573] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-7.fc28.x86_64/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5/conf/cyrus.conf" "-L" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5/conf/master.log"
=====> Instance[1649] rlimits: $VAR1 = {
  'RLIMIT_AS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_CORE' => [
    '104857600',
    '104857600'
  ],
  'RLIMIT_CPU' => [
    '-1',
    '-1'
  ],
  'RLIMIT_DATA' => [
    '-1',
    '-1'
  ],
  'RLIMIT_FSIZE' => [
    '-1',
    '-1'
  ],
  'RLIMIT_LOCKS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_MEMLOCK' => [
    '65536',
    '65536'
  ],
  'RLIMIT_MSGQUEUE' => [
    '819200',
    '819200'
  ],
  'RLIMIT_NICE' => [
    '0',
    '0'
  ],
  'RLIMIT_NOFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_NPROC' => [
    '515267',
    '515267'
  ],
  'RLIMIT_OFILE' => [
    '1024',
    '4096'
  ],
  'RLIMIT_OPEN_MAX' => [
    '1024',
    '4096'
  ],
  'RLIMIT_RSS' => [
    '-1',
    '-1'
  ],
  'RLIMIT_RTPRIO' => [
    '0',
    '0'
  ],
  'RLIMIT_RTTIME' => [
    '-1',
    '-1'
  ],
  'RLIMIT_SIGPENDING' => [
    '515267',
    '515267'
  ],
  'RLIMIT_STACK' => [
    '8388608',
    '-1'
  ],
  'RLIMIT_VMEM' => [
    '-1',
    '-1'
  ]
};
=====> Instance[891] _start_master: waiting for PID file
=====> Instance[894] _start_master: PID file present and correct
=====> Instance[906] _start_master: PID waiting for services
=====> Daemon[356] is_listening: service lmtp is listening on /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5/conf/socket/lmtp
=====> Util::Wait[75] Waited 0.095819 sec for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/053116]5/conf/socket/lmtp to be in LISTEN state
=====> Daemon[356] is_listening: service imap is listening on 127.0.0.1:9671
=====> Instance[917] _start_master: all services listening
=====> Instance[993] create user cassandane
=====> Util::Socket[61] create_client_socket INET host=127.0.0.1 port=9671
C: 1 capability
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] buildhw-02.phx2.fedoraproject.org Cyrus IMAP 3.0.5-7.fc28 Fedora server ready
S: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY AUTH=PLAIN AUTH=LOGIN SASL-IR COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE
S: 1 OK Completed
C: 2 login admin "testpw"
=====> Instance[1851] authdaemon connection: admin testpw imap 
S: 2 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY LOGINDISABLED COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] User logged in SESSIONID=<053116]5-1264-1523079082-1-8008635740833030301>
C: 3 create user.cassandane
S: 3 OK Completed
C: 4 setacl user.cassandane admin lrswipkxtecdan
S: 4 OK Completed
C: 5 setacl user.cassandane cassandane lrswipkxtecdn
S: 5 OK Completed
C: 6 setacl user.cassandane anyone p
S: 6 OK Completed
A: is_open test
A: is_open test received timeout, still open
C: 7 logout
S: * BYE LOGOUT received
S: 7 OK Completed
A: Release socket, fileno=66
=====> Instance[1103] started main instance for test test_basic_idled: cyrus version 3.0.5-7.fc28 Fedora
=====> Util::Socket[61] create_client_socket INET host=127.0.0.1 port=9671
C: 1 capability
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] buildhw-02.phx2.fedoraproject.org Cyrus IMAP 3.0.5-7.fc28 Fedora server ready
S: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY AUTH=PLAIN AUTH=LOGIN SASL-IR COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE
S: 1 OK Completed
C: 2 login cassandane "testpw"
=====> Instance[1851] authdaemon connection: cassandane testpw imap 
S: 2 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION URLAUTH URLAUTH=BINARY LOGINDISABLED COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] User logged in SESSIONID=<053116]5-1264-1523079083-1-11656135676930622992>
C: 3 select "INBOX"
S: * 0 EXISTS
S: * 0 RECENT
S: * FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
S: * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)] Ok
S: * OK [UIDVALIDITY 1523079083] Ok
S: * OK [UIDNEXT 1] Ok
S: * OK [HIGHESTMODSEQ 3] Ok
S: * OK [URLMECH INTERNAL] Ok
S: * OK [ANNOTATIONS 65536] Ok
S: 3 OK [READ-WRITE] Completed
=====> Cyrus::Idle[154] The server should report the IDLE capability
A: is_open test
A: is_open test received timeout, still open
C: 4 logout
S: * BYE LOGOUT received
S: 4 OK Completed
A: Release socket, fileno=66
=====> Cyrus::TestCase[679] Beginning tear_down
=====> Instance[1310] stop
=====> Instance[1272] _stop_pid: sending signal 15 to 1108
=====> Util::Wait[75] Waited 0.010097 sec for unknown condition
=====> Instance[1054] killing smtpd 953
2018/04/07-05:31:23 Server closing!
=====> Instance[942] killing saslauthd 991
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at /usr/lib64/perl5/IO/Select.pm line 120.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at /usr/lib64/perl5/IO/Select.pm line 120.
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 936.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 936.
=====> Instance[1054] killing smtpd 953
=====> Instance[969] killing notifyd 996
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 963.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 963.
=====> Instance[1054] killing smtpd 953
=====> Instance[942] killing saslauthd 991
=====> Cyrus::TestCase[724] ---------- END test_basic_idled ----------
=====> Daemon[385] checking for stray processes on ports: 9670 9671
Test was not successful.

[jasontibbitts]

I edited the title to more accurately reflect what's happening.

In any case, the issue seems pretty obvious; as $workerid gets to be greater than 26, chr(64 + $workerid) goes past Z and becomes [ and then \. When unpackfile tries to shell out to tar, the backslash actually gets interpreted as an escape character and things fail. So basically, the recipe for failure is that worker 28 has to run one of the tests which will call unpackfile (or some other function which calls run_command, I guess). I am not sure if it's just 28 or if other values which map to shell metacharacters will do it. It looks like everything is done so that perl's exec is called with a list, so perl will just call execvp and the shell shouldn't be involved. But.... I don't know. Perl may have magic involved there, or tar itself just might not like it.

But in any case, that explains why it happens so intermittently. There are only those six values before you get back into alphabetics so you'd have to get up to workerid 59 to run out of letters again. I don't know how high it's expected to go in a normal run, really.

[elliefm]

Yep, that'd be my analysis too.

I'm not confident in my understanding of when/why Workers are allocated, but it seems clear that it's not merely "one Worker per -j job". It might be "one worker per process that Cassandane forks", which would include all the master, imapd, httpd, sync_client, etc processes that get run and everything as well... in which case, 26 seems like a ridiculously low limit! (Some of our tests, especially replication and murder, are running multiple Cyrus instances in parallel, each with the usual assortment of processes....)

So the fix for this will be fixing _make_unique_instance_info to be less boneheaded :) I'll get onto that, thanks for sticking with this and providing the diagnostics!

[elliefm]

Should be fixed now -- but please let me know if my "fixed" implementation turns out to be boneheaded in its own way! :P

[elliefm]

For what it's worth, I've just done a couple of runs against cyrus master here with -j40 and -j50 (on a VM with 2 cores...) and under that sorta load, the only repeated failures are Master.maxforkrate (seems sensible) and a couple of the CaldavAlarm.*_multiuser tests (which I guess might have timestamp checks in them, I haven't investigated deeper).

Which tells us something about how it performs under load, but also suggests that massive amounts of workers aren't breaking in any weird ways, hooray. :)

[jasontibbitts]

Thanks. I think what you committed should do it. I've updated everything and I guess we'll just have to wait and see if I see I get any more bizarre failures.