Skip to content
This repository has been archived by the owner on Dec 10, 2024. It is now read-only.

Newly added tests failing when run against cyrus 3.0.5 #54

Open
jasontibbitts opened this issue Apr 11, 2018 · 8 comments
Open

Newly added tests failing when run against cyrus 3.0.5 #54

jasontibbitts opened this issue Apr 11, 2018 · 8 comments

Comments

@jasontibbitts
Copy link

jasontibbitts commented Apr 11, 2018 •
edited
Loading

I updated Cassandane and now have a few failing tests when running against 3.0.5. Commit 191b1cc introduced a problem which was fixed by 9aa93b7 but in between the Sieve.editheader test was added, and that errors out because of:

=====> Instance[1595] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/sbin/sievec" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/164348D32/conf/imapd.conf" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/164348D32/conf/sieve/c/cassandane/test1.script" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/164348D32/conf/sieve/c/cassandane/test1.bc"
Unable to parse script: script errors:
line 1: Unsupported feature(s) in "require": "editheader"

I'm not sure which version of the cyrus code supports that sieve extension, but the test probably needs a :min_version annotation.

There are quite similar failures for Sieve.duplicate (line 1: Unsupported feature(s) in "require": "duplicate") and Sieve.ereject (line 1: Unsupported feature(s) in "require": "ereject").

Finally, the Sieve.rfc5490_mailboxexists_variables which was also added recently fails, but I'm not entirely sure what's gone wrong. The Cassandane output is below.

Because I'd like that added feature of changing the port base, I'll just skip these failing tests for now.

1) test_rfc5490_mailboxexists_variables(Cassandane::Cyrus::Sieve)
 expected 1, got 2 at Cassandane/Cyrus/TestCase.pm line 814.
        Cassandane::Cyrus::TestCase::check_messages(Cassandane::Cyrus::Sieve=HASH(0x55d8fdcf5678), HASH(0x55d8fe727db0), "check_guid", 0) called at Cassandane/Cyrus/Sieve.pm line 755
        Cassandane::Cyrus::Sieve::test_rfc5490_mailboxexists_variables(Cassandane::Cyrus::Sieve=HASH(0x55d8fdcf5678)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
        [...framework calls elided...]
Annotations:
=====> Cyrus::TestCase[565] ---------- BEGIN test_rfc5490_mailboxexists_variables ----------
=====> Instance[289] name: 172841F24, basedir: /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24
=====> Instance[1076] start main instance for test test_rfc5490_mailboxexists_variables: basedir /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24
=====> Instance[1059] started smtpd as 3839
=====> Instance[476] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/sbin
=====> Instance[476] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/sbin
=====> Instance[1595] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/conf/imapd.conf"
2018/04/11-12:29:01 Cassandane::Net::SMTPServer (type Net::Server::PreForkSimple) starting! pid(3839)
Resolved [localhost]:19216 to [::1]:19216, IPv6
Resolved [localhost]:19216 to [127.0.0.1]:19216, IPv4
Binding to TCP port 19216 on host ::1 with IPv6
Binding to TCP port 19216 on host 127.0.0.1 with IPv4
Group Not Defined.  Defaulting to EGID '135 135'
User Not Defined.  Defaulting to EUID '7225'
=====> Instance[476] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/sbin
=====> Instance[476] Found binary timsieved in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/libexec/cyrus-imapd
=====> Instance[476] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/libexec/cyrus-imapd
=====> Instance[476] Found binary lmtpd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/libexec/cyrus-imapd
=====> Instance[947] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24 as 3854
=====> Instance[1858] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/run/mux
=====> Instance[974] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24 as 3855
=====> Instance[890] _start_master: logging to /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/conf/master.log
=====> Instance[476] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/libexec/cyrus-imapd
=====> Instance[1595] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/conf/cyrus.conf" "-L" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/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 sieve is listening on 127.0.0.1:19217
=====> Util::Wait[75] Waited 0.053971 sec for 127.0.0.1:19217 to be in LISTEN state
=====> Daemon[356] is_listening: service imap is listening on 127.0.0.1:19218
=====> Daemon[356] is_listening: service lmtp is listening on /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/conf/socket/lmtp
=====> 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=19218
C: 1 capability
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] epithumnia.math.uh.edu 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=<172841F24-3969-1523467741-1-12487705119661140012>
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=22
=====> Instance[1111] started main instance for test test_rfc5490_mailboxexists_variables: cyrus version 3.0.5-12.fc29 Fedora
=====> Cyrus::TestCase[572] Calling test function
=====> Cyrus::Sieve[707] Testing the "mailboxexists" test with variables
=====> Util::Socket[61] create_client_socket INET host=127.0.0.1 port=19218
C: 1 capability
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] epithumnia.math.uh.edu 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=<172841F24-3969-1523467741-2-16514598766706978163>
=====> Cyrus::Sieve[715] Install the sieve script
=====> Instance[1995] Installing sieve script test1 in /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/conf/sieve/c/cassandane
=====> Instance[476] Found binary sievec in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/sbin
=====> Instance[1595] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/sbin/sievec" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/conf/imapd.conf" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/conf/sieve/c/cassandane/test1.script" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/conf/sieve/c/cassandane/test1.bc"
=====> Instance[2016] Sieve script installed successfully
C: 3 create INBOX.newfolder
S: 3 OK Completed
=====> Cyrus::Sieve[730] Deliver a message
=====> Instance[476] Found binary deliver in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/sbin
=====> Instance[1595] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/sbin/deliver" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/conf/imapd.conf" "cassandane"
=====> Cyrus::Sieve[739] Create the test folder
C: 4 create INBOX.testfolder
S: 4 OK Completed
=====> Cyrus::Sieve[742] Deliver a message now that the folder exists
=====> Instance[476] Found binary deliver in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/sbin
=====> Instance[1595] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-12.fc29.x86_64/usr/sbin/deliver" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/172841F24/conf/imapd.conf" "cassandane"
=====> Cyrus::Sieve[751] Check that the messages made it
=====> Cyrus::TestCase[798] check_messages: check_guid 0
C: 5 select "INBOX"
S: * 2 EXISTS
S: * 2 RECENT
S: * FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
S: * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)] Ok
S: * OK [UNSEEN 1] Ok
S: * OK [UIDVALIDITY 1523467742] Ok
S: * OK [UIDNEXT 3] Ok
S: * OK [HIGHESTMODSEQ 5] Ok
S: * OK [URLMECH INTERNAL] Ok
S: * OK [ANNOTATIONS 65536] Ok
S: 5 OK [READ-WRITE] Completed
C: 6 fetch 1:2 (uid body.peek[])
S: * 1 FETCH (UID 1 BODY[] {985}
S: )
S: * 2 FETCH (UID 2 BODY[] {983}
S: )
S: 6 OK Completed (0.000 sec)
=====> Cyrus::TestCase[679] Beginning tear_down
C: 7 logout
S: * BYE LOGOUT received
S: 7 OK Completed
A: Release socket, fileno=22
=====> Instance[1318] stop
=====> Instance[1280] _stop_pid: sending signal 15 to 3914
=====> Util::Wait[75] Waited 0.010089 sec for unknown condition
=====> Instance[1062] killing smtpd 3839
2018/04/11-12:29:01 Server closing!
=====> Instance[950] killing saslauthd 3854
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 /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 Cassandane/Instance.pm line 944.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 944.
=====> Instance[1062] killing smtpd 3839
=====> Instance[977] killing notifyd 3855
Warning: unable to close filehandle $olderr properly: Bad file descriptor at Cassandane/Instance.pm line 971.
Warning: unable to close filehandle $oldout properly: Bad file descriptor at Cassandane/Instance.pm line 971.
=====> Instance[1062] killing smtpd 3839
=====> Instance[950] killing saslauthd 3854
=====> Cyrus::TestCase[724] ---------- END test_rfc5490_mailboxexists_variables ----------
=====> Daemon[385] checking for stray processes on ports: 19216 19217 19218
Test was not successful.
@elliefm
Copy link
Contributor

elliefm commented Apr 13, 2018

I've marked the editheader, duplicate and ereject tests as min_version_3_1, so they won't try to run against 3.0 anymore.

I think test_rfc5490_mailboxexists_variables may have turned up a bug in the 3.0, so it's correct for that to be failing for now. I'll keep poking around at it and see if I can understand it, and then either fix it or open an issue for Ken.

@elliefm
Copy link
Contributor

elliefm commented Apr 13, 2018

Here's another variation on the same issue:

1) test_rfc5490_mailboxexists_variables(Cassandane::Cyrus::Sieve)
 expected 1, got 0 at Cassandane/Cyrus/TestCase.pm line 814.
	Cassandane::Cyrus::TestCase::check_messages(Cassandane::Cyrus::Sieve=HASH(0x55bc103a6030), HASH(0x55bc103e4e58), "check_guid", 0) called at Cassandane/Cyrus/Sieve.pm line 757
	Cassandane::Cyrus::Sieve::test_rfc5490_mailboxexists_variables(Cassandane::Cyrus::Sieve=HASH(0x55bc103a6030)) called at /usr/share/perl5/Test/Unit/TestCase.pm line 75
	[...framework calls elided...]

This test sets up a sieve script that looks for the existence of a test mailbox. If the mailbox exists, the message is delivered into a hit mailbox, otherwise the message is delivered into a miss mailbox.

Then, the test does the following:

  • deliver a message
  • create the test mailbox
  • deliver a message
  • expect the first message to land in the miss mailbox, and the second one to land in the hit mailbox

So, it expects to find one message in each folder. But sometimes it's failing because they're both in the first folder it looked in, and sometimes it's failing because neither of them are in the first folder it looked in. I'm not yet sure what significance the order holds, but it seems clear that both messages always deliver to the same folder, which is definitely wrong no matter which folder it was.

@elliefm elliefm mentioned this issue Apr 13, 2018
Closed
@elliefm
Copy link
Contributor

elliefm commented Apr 13, 2018

I've opened up cyrusimap/cyrus-imapd#2317 for the mailboxexists-variables test failure

@jasontibbitts
Copy link
Author

I guess you can add the Objectid.uniqueid test to the list of things which shouldn't be run on 3.0.

1) test_uniqueid(Cassandane::Cyrus::Objectid)
 expected value was undef; should be using assert_null? at Cassandane/Cyrus/Objectid.pm line 91.
        Cassandane::Cyrus::Objectid::test_uniqueid(Cassandane::Cyrus::Objectid=HASH(0x56430fe73dc8)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
        [...framework calls elided...]
Annotations:
=====> Cyrus::TestCase[565] ---------- BEGIN test_uniqueid ----------
=====> Cyrus::TestCase[167] Magic attribute AltNamespace sets config altnamespace = yes
=====> Instance[1074] start main instance for test test_uniqueid: basedir /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1709561012
=====> Instance[1057] started smtpd as 54297
=====> Instance[473] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-13.fc29.x86_64/usr/sbin
=====> Instance[473] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-13.fc29.x86_64/usr/sbin
=====> Instance[1593] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-13.fc29.x86_64/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1709561012/conf/imapd.conf"
2018/04/13-12:10:09 Cassandane::Net::SMTPServer (type Net::Server::PreForkSimple) starting! pid(54297)
Resolved [localhost]:19419 to [::1]:19419, IPv6
Resolved [localhost]:19419 to [127.0.0.1]:19419, IPv4
Binding to TCP port 19419 on host ::1 with IPv6
Binding to TCP port 19419 on host 127.0.0.1 with IPv4
Group Not Defined.  Defaulting to EGID '135 135'
User Not Defined.  Defaulting to EUID '7225'
=====> Instance[473] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-13.fc29.x86_64/usr/sbin
=====> Instance[473] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-13.fc29.x86_64/usr/libexec/cyrus-imapd
=====> Instance[945] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1709561012 as 54327
=====> Instance[1856] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1709561012/run/mux
=====> Instance[972] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1709561012 as 54333
=====> Instance[888] _start_master: logging to /builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1709561012/conf/master.log
=====> Instance[473] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.5-13.fc29.x86_64/usr/libexec/cyrus-imapd
=====> Instance[1593] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.5-13.fc29.x86_64/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1709561012/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1709561012/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1709561012/conf/cyrus.conf" "-L" "/builddir/build/BUILD/cyrus-imapd-3.0.5/cassandane/work/1709561012/conf/master.log"
=====> 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:19400
=====> Util::Wait[75] Waited 0.054581 sec for 127.0.0.1:19400 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=19400
C: 1 capability
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] epithumnia.math.uh.edu Cyrus IMAP 3.0.5-13.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[1871] 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=<1709561012-54430-1523639409-1-15527374838680525332>
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=43
=====> Instance[1109] started main instance for test test_uniqueid: cyrus version 3.0.5-13.fc29 Fedora
=====> Cyrus::TestCase[572] Calling test function
=====> Util::Socket[61] create_client_socket INET host=127.0.0.1 port=19400
C: 1 capability
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] epithumnia.math.uh.edu Cyrus IMAP 3.0.5-13.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[1871] 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=<1709561012-54430-1523639409-2-6403380486990594010>
=====> Util::Socket[61] create_client_socket INET host=127.0.0.1 port=19400
C: 1 capability
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] epithumnia.math.uh.edu Cyrus IMAP 3.0.5-13.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[1871] 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=<1709561012-54446-1523639409-1-3886228502631936170>
C: 3 create foo
S: 3 OK Completed
C: 4 create bar
S: 4 OK Completed
C: 5 status foo (mailboxid uidvalidity)
S: 5 BAD Invalid Status attributes mailboxid
C: 6 status bar (mailboxid uidvalidity)
S: * BAD Invalid tag
S: 6 BAD Invalid Status attributes mailboxid
C: 7 rename foo renamed
S: * BAD Invalid tag
S: * OK rename foo renamed
S: 7 OK Completed
C: 8 status renamed (mailboxid uidvalidity)
S: 8 BAD Invalid Status attributes mailboxid
C: 9 status bar (mailboxid uidvalidity)
S: * BAD Invalid tag
S: 9 BAD Invalid Status attributes mailboxid
=====> Cyrus::TestCase[679] Beginning tear_down
C: 10 logout
S: * BAD Invalid tag
S: * BYE LOGOUT received
S: 10 OK Completed
A: Release socket, fileno=44
C: 3 logout
S: * BYE LOGOUT received
S: 3 OK Completed
A: Release socket, fileno=43
=====> Instance[1316] stop
=====> Instance[1278] _stop_pid: sending signal 15 to 54388
=====> Util::Wait[75] Waited 0.010096 sec for unknown condition
=====> Instance[1060] killing smtpd 54297
2018/04/13-12:10:09 Server closing!
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 /usr/lib64/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/share/perl5/vendor_perl/Net/Server/PreForkSimple.pm line 214.
=====> Instance[948] killing saslauthd 54327
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 54297
=====> Instance[975] killing notifyd 54333
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 54297
=====> Instance[948] killing saslauthd 54327
=====> Cyrus::TestCase[724] ---------- END test_uniqueid ----------
=====> Daemon[385] checking for stray processes on ports: 19400 19419
Test was not successful.

@elliefm
Copy link
Contributor

elliefm commented Apr 16, 2018

Ah yep, and the other Objectid test too from the look of things (I think the only reason it doesn't currently fail on 3.0 is because it doesn't currently test anything....). Fixed in d01f921

@jasontibbitts
Copy link
Author

Thanks! Unfortunately I'm going to be blocked on the requirement for Mail::JMAPTalk 0.11 for a while (since it's required by Cassandane since ab7a87b but doesn't yet exist on CPAN). But I think as a whole my use of Cassandane is in a good place. I'm excluding fewer tests than I was before and I think the intermittent failures are gone.

@elliefm
Copy link
Contributor

elliefm commented Apr 18, 2018

Yeah I'm blocked on that too, I install that module from CPAN myself!

@elliefm
Copy link
Contributor

elliefm commented Apr 18, 2018

For the record, the test_rfc5490_mailboxexists_variables failure was a cyrus bug (#2317), but it's now fixed in git and will be included in 3.0.6

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jasontibbitts @elliefm