search

cyrusimap / cyrus-imapd

Cyrus IMAP is an email, contacts and calendar server
http://cyrusimap.org
Other
543 stars 149 forks source link

Cassandane failure in JMAPCalendars.setcalendarevents_alerts #2048

Closed jasontibbitts closed 5 years ago

jasontibbitts commented 7 years ago

This is the last of my unexplained failures, and it happens consistently across all architectures. This is with 3.0.2 plus the two patches from #2042, and a Cassandane checkout from June 22. In this case, libical has been compiled with the flag allowing empty properties, though that doesn't appear to make any difference for this test.

1) test_setcalendarevents_alerts(Cassandane::Cyrus::JMAPCalendars)
 Structures begin differing at:
  $a->{useDefaultAlerts} = Does not exist
  $b->{useDefaultAlerts} = '1'
 at Cassandane/Cyrus/JMAPCalendars.pm line 604.
        Cassandane::Cyrus::JMAPCalendars::assert_normalized_event_equals(Cassandane::Cyrus::JMAPCalendars=HASH(0x5648da98e6d8), HASH(0x5648dae38e60), HASH(0x5648daa3eae0)) called at Cassandane/Cyrus/JMAPCalendars.pm line 1663
        Cassandane::Cyrus::JMAPCalendars::test_setcalendarevents_alerts(Cassandane::Cyrus::JMAPCalendars=HASH(0x5648da98e6d8)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
        [...framework calls elided...]

Annotations:
=====> Cyrus::TestCase[567] ---------- BEGIN test_setcalendarevents_alerts ----------
=====> Cyrus::TestCase[160] Magic attribute JMAP wants jmap = 1
=====> Cyrus::TestCase[160] Magic attribute JMAP wants adminstore = 1
=====> Cyrus::TestCase[160] Magic attribute JMAP wants services = ARRAY(0x5648da990128)
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config caldav_realm = Cassandane
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config conversations = yes
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config httpmodules = carddav caldav jmap
=====> Cyrus::TestCase[169] Magic attribute JMAP sets config httpallowcompress = no
=====> Instance[1004] start main instance for test test_setcalendarevents_alerts: basedir /builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181
=====> Instance[455] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/sbin
=====> Instance[455] Found binary cyr_buildinfo in /builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/sbin
=====> Instance[1505] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/sbin/cyr_buildinfo" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/imapd.conf"
=====> Instance[455] Found binary ctl_cyrusdb in /builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/sbin
=====> Instance[455] Found binary imapd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/libexec/cyrus-imapd
=====> Instance[455] Found binary httpd in /builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/libexec/cyrus-imapd
=====> Instance[916] started saslauthd for /builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181 as 19719
=====> Instance[1759] opening socket /builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/run/mux
=====> Instance[943] started notifyd for /builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181 as 19720
=====> Instance[455] Found binary master in /builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/libexec/cyrus-imapd
=====> Instance[1505] Running: "/builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/libexec/cyrus-imapd/master" "-C" "/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/imapd.conf" "-l" "255" "-p" "/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/run/master.pid" "-d" "-M" "/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/cyrus.conf"
=====> Instance[868] _start_master: waiting for PID file
=====> Instance[871] _start_master: PID file present and correct
=====> Instance[883] _start_master: PID waiting for services
=====> Daemon[358] is_listening: service imap is listening on 127.0.0.1:9100
=====> Util::Wait[77] Waited 0.054475 sec for 127.0.0.1:9100 to be in LISTEN state
=====> Daemon[358] is_listening: service http is listening on 127.0.0.1:9101
=====> Instance[894] _start_master: all services listening
=====> Instance[970] create user cassandane
=====> Util::Socket[63] create_client_socket INET host=127.0.0.1 port=9100
=====> Instance[1774] authdaemon connection: admin testpw imap 
=====> Instance[1035] started main instance for test test_setcalendarevents_alerts: cyrus version 3.0.2-5.fc27 Fedora
=====> Instance[1774] authdaemon connection: cassandane pass http 
=====> Instance[1774] authdaemon connection: cassandane pass http 
=====> Instance[1774] authdaemon connection: cassandane pass http 
=====> Instance[1774] authdaemon connection: cassandane pass http 
=====> Instance[1774] authdaemon connection: cassandane pass http 
=====> Instance[1774] authdaemon connection: cassandane pass http 
=====> Cyrus::TestCase[574] Calling test function
=====> Cyrus::JMAPCalendars[71] Requesting JMAP access token
JMAP $VAR1 = {
  'clientName' => 'Net-JMAPTalk',
  'clientVersion' => '0.07',
  'deviceName' => 'api',
  'username' => 'cassandane'
};
$VAR2 = {
  'content' => '{"loginId": "014c3076590b335456295ddf7cbe3d1d570b201185ef17e295ee0286b5172d44fe952c76d6bc", "methods": [{"type": "password"}], "prompt": null}',
  'headers' => {
    'connection' => 'Upgrade',
    'content-length' => '142',
    'content-type' => 'application/json; charset=utf-8',
    'date' => 'Mon, 03 Jul 2017 18:53:18 GMT',
    'upgrade' => 'h2c',
    'vary' => 'Accept-Encoding'
  },
  'protocol' => 'HTTP/1.1',
  'reason' => 'OK',
  'status' => '200',
  'success' => 1,
  'url' => 'http://127.0.0.1:9101/jmap/auth/'
};
=====> Instance[1774] authdaemon connection: cassandane pass http 
JMAP $VAR1 = {
  'loginId' => '014c3076590b335456295ddf7cbe3d1d570b201185ef17e295ee0286b5172d44fe952c76d6bc',
  'password' => 'pass',
  'type' => 'password'
};
$VAR2 = {
  'content' => '{"username": "cassandane", "accounts": {"cassandane": {"name": "cassandane", "isPrimary": true, "isReadOnly": false}}, "apiUrl": "/jmap/", "downloadUrl": "/jmap/download/{accountId}/{blobId}/{name}", "uploadUrl": "/jmap/upload/", "accessToken": "014186c3d47630f1dbdddc7bb81f7dbe3b08c3f3893318fc9beb11fb842c846a422bcce905d3"}',
  'headers' => {
    'connection' => 'Upgrade',
    'content-length' => '324',
    'content-type' => 'application/json; charset=utf-8',
    'date' => 'Mon, 03 Jul 2017 18:53:18 GMT',
    'upgrade' => 'h2c',
    'vary' => 'Accept-Encoding'
  },
  'protocol' => 'HTTP/1.1',
  'reason' => 'Created',
  'status' => '201',
  'success' => 1,
  'url' => 'http://127.0.0.1:9101/jmap/auth/'
};
=====> Cyrus::JMAPCalendars[1063] create event
JMAP $VAR1 = [
  [
    'setCalendarEvents',
    {
      'create' => {
        '1' => {
          'alerts' => {
            'alert1' => {
              'action' => {
                'acknowledged' => '2015-11-07T08:57:00Z',
                'subject' => 'foo',
                'textBody' => 'bar',
                'to' => [
                  {
                    'email' => 'foo@example.com',
                    'name' => ''
                  }
                ],
                'type' => 'email'
              },
              'offset' => 'PT5M',
              'relativeTo' => 'before-start'
            },
            'alert2' => {
              'action' => {
                'snoozed' => '2015-11-07T10:05:00Z',
                'type' => 'display'
              },
              'offset' => 'PT1H',
              'relativeTo' => 'after-start'
            }
          },
          'calendarId' => 'Default',
          'description' => 'description',
          'duration' => 'PT2H',
          'freeBusyStatus' => 'busy',
          'isAllDay' => bless( do{\(my $o = 0)}, 'JSON::PP::Boolean' ),
          'start' => '2015-11-07T09:00:00',
          'status' => 'confirmed',
          'timeZone' => 'Europe/London',
          'title' => 'title',
          'useDefaultAlerts' => bless( do{\(my $o = 1)}, 'JSON::PP::Boolean' )
        }
      }
    },
    'R1'
  ]
];
$VAR2 = {
  'content' => '[
  [
    "calendarEventsSet",
    {
      "accountId": "cassandane",
      "oldState": "22",
      "created": {
        "1": {
          "id": "fc0e8106-d040-48a1-ba15-435d33d4222a"
        }
      },
      "newState": "24"
    },
    "R1"
  ]
]',
  'headers' => {
    'connection' => 'Upgrade',
    'content-length' => '246',
    'content-type' => 'application/json; charset=utf-8',
    'date' => 'Mon, 03 Jul 2017 18:53:18 GMT',
    'upgrade' => 'h2c',
    'vary' => 'Accept-Encoding'
  },
  'protocol' => 'HTTP/1.1',
  'reason' => 'OK',
  'status' => '200',
  'success' => 1,
  'url' => 'http://127.0.0.1:9101/jmap/'
};
=====> Cyrus::JMAPCalendars[1068] get calendar event fc0e8106-d040-48a1-ba15-435d33d4222a
JMAP $VAR1 = [
  [
    'getCalendarEvents',
    {
      'ids' => [
        'fc0e8106-d040-48a1-ba15-435d33d4222a'
      ]
    },
    'R1'
  ]
];
$VAR2 = {
  'content' => '[
  [
    "calendarEvents",
    {
      "state": "24",
      "accountId": "cassandane",
      "list": [
        {
          "isAllDay": false,
          "uid": "fc0e8106-d040-48a1-ba15-435d33d4222a",
          "relatedTo": null,
          "prodId": "-//CyrusJMAP.org/Cyrus 3.0.2-5.fc27 Fedora//EN",
          "created": "2017-07-03T18:53:18Z",
          "updated": "2017-07-03T18:53:18Z",
          "sequence": 0,
          "title": "title",
          "description": "description",
          "links": null,
          "locale": null,
          "locations": null,
          "start": "2015-11-07T09:00:00",
          "timeZone": "Europe/London",
          "duration": "PT2H",
          "recurrenceRule": null,
          "status": "confirmed",
          "freeBusyStatus": "busy",
          "privacy": "public",
          "replyTo": null,
          "participants": null,
          "alerts": {
            "alert2": {
              "relativeTo": "after-start",
              "offset": "PT1H",
              "action": {
                "type": "display",
                "snoozed": "2015-11-07T10:05:00Z"
              }
            },
            "alert1": {
              "relativeTo": "before-start",
              "offset": "PT5M",
              "action": {
                "type": "email",
                "to": [
                  {
                    "name": "",
                    "email": "foo@example.com"
                  }
                ],
                "subject": "foo",
                "textBody": "bar",
                "acknowledged": "2015-11-07T08:57:00Z"
              }
            }
          },
          "localizations": null,
          "recurrenceOverrides": null,
          "x-href": "/dav/calendars/user/cassandane/Default/fc0e8106-d040-48a1-ba15-435d33d4222a.ics",
          "calendarId": "Default",
          "id": "fc0e8106-d040-48a1-ba15-435d33d4222a"
        }
      ],
      "notFound": null
    },
    "R1"
  ]
]',
  'headers' => {
    'connection' => 'Upgrade',
    'content-length' => '1945',
    'content-type' => 'application/json; charset=utf-8',
    'date' => 'Mon, 03 Jul 2017 18:53:18 GMT',
    'upgrade' => 'h2c',
    'vary' => 'Accept-Encoding'
  },
  'protocol' => 'HTTP/1.1',
  'reason' => 'OK',
  'status' => '200',
  'success' => 1,
  'url' => 'http://127.0.0.1:9101/jmap/'
};
=====> Cyrus::TestCase[681] Beginning tear_down
=====> Instance[1242] stop
=====> Instance[1204] _stop_pid: sending signal 15 to 19725
=====> Util::Wait[77] Waited 0.010099 sec for unknown condition
=====> Instance[919] killing saslauthd 19719
=====> Instance[946] killing notifyd 19720
=====> Instance[919] killing saslauthd 19719
=====> Cyrus::TestCase[726] ---------- END test_setcalendarevents_alerts ----------
=====> Daemon[387] checking for stray processes on ports: 9100 9101

This is the syslog output:

1853181/master[19725]: process started
1853181/master[19728]: about to exec /builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/sbin/ctl_cyrusdb
1853181/ctl_cyrusdb[19728]: skiplist: clean shutdown file missing, updating recovery stamp
1853181/ctl_cyrusdb[19728]: SQL backend defaulting to engine 'pgsql'
1853181/ctl_cyrusdb[19728]: recovering cyrus databases
1853181/ctl_cyrusdb[19728]: done recovering cyrus databases
1853181/master[19725]: process type:START name:recover path:/builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/sbin/ctl_cyrusdb age:0.000s pid:19728 exited normally
1853181/master[19725]: ready for work
1853181/master[19731]: about to exec /builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/libexec/cyrus-imapd/imapd
1853181/imap[19731]: SQL backend defaulting to engine 'pgsql'
1853181/imap[19731]: executed
1853181/imap[19731]: accepted connection
1853181/imap[19731]: command: 1 Capability
1853181/imap[19731]: command: 2 Login
[127.0.0.1] admin plaintext User logged in SESSIONID=<1853181-19731-1499107998-1-1786010344523871877>
1853181/imap[19731]: command: 3 Create
1853181/imap[19731]: auditlog: create sessionid=<1853181-19731-1499107998-1-1786010344523871877> mailbox=<user.cassandane> uniqueid=<5fa107ad-07a2-4401-bdcf-422bd0324676> uidvalidity=<1499107999>
1853181/imap[19731]: NOTIFY: response OK to method pusher
1853181/imap[19731]: command: 4 Setacl
1853181/imap[19731]: auditlog: acl sessionid=<1853181-19731-1499107998-1-1786010344523871877> mailbox=<user.cassandane> uniqueid=<5fa107ad-07a2-4401-bdcf-422bd0324676> oldacl=<cassandane        lrswipkxtecdan        > acl=<cassandane        lrswipkxtecdan        admin        lrswipkxtecdan        >
1853181/imap[19731]: NOTIFY: response OK to method pusher
1853181/imap[19731]: auditlog: modseq sessionid=<1853181-19731-1499107998-1-1786010344523871877> mailbox=<user.cassandane> uniqueid=<5fa107ad-07a2-4401-bdcf-422bd0324676> highestmodseq=<2>
1853181/imap[19731]: command: 5 Setacl
1853181/imap[19731]: NOTIFY: response OK to method pusher
1853181/imap[19731]: command: 6 Setacl
1853181/imap[19731]: auditlog: acl sessionid=<1853181-19731-1499107998-1-1786010344523871877> mailbox=<user.cassandane> uniqueid=<5fa107ad-07a2-4401-bdcf-422bd0324676> oldacl=<cassandane        lrswipkxtecdan        admin        lrswipkxtecdan        > acl=<cassandane        lrswipkxtecdan        admin        lrswipkxtecdan        anyone        p        >
1853181/imap[19731]: NOTIFY: response OK to method pusher
1853181/imap[19731]: auditlog: modseq sessionid=<1853181-19731-1499107998-1-1786010344523871877> mailbox=<user.cassandane> uniqueid=<5fa107ad-07a2-4401-bdcf-422bd0324676> highestmodseq=<3>
1853181/imap[19731]: command: 7 Logout
1853181/imap[19731]: USAGE admin user: 0.013623 sys: 0.007380
1853181/imap[19731]: auditlog: traffic sessionid=<1853181-19731-1499107998-1-1786010344523871877> bytes_in=<207> bytes_out=<1630>
1853181/master[19732]: about to exec /builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/libexec/cyrus-imapd/httpd
1853181/http[19732]: SQL backend defaulting to engine 'pgsql'
1853181/http[19732]: executed
1853181/http[19732]: accepted connection
1853181/http[19732]: read & parse request-line
1853181/http[19732]: read & parse headers
1853181/http[19732]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19732]: write_body(code = -1964266999, flags.te = 0, len = 0)
1853181/http[19732]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19732]: simple_hdr(Connection: Upgrade)
1853181/http[19732]: simple_hdr(Upgrade: h2c)
1853181/http[19732]: simple_hdr(Location: http://127.0.0.1:9101/dav/addressbooks)
1853181/http[19732]: simple_hdr(Vary: Accept-Encoding)
1853181/http[19732]: simple_hdr(Content-Length: 0)
[127.0.0.1] with "Net-DAVTalk/0.01"; "PROPFIND /.well-known/carddav HTTP/1.1" (depth=0) => "HTTP/1.1 301 Moved Permanently" (location=http://127.0.0.1:9101/dav/addressbooks)
1853181/http[19732]: read_body(flags=0x10, framing=2)
1853181/http[19732]: read & parse request-line
1853181/http[19732]: read & parse headers
1853181/http[19732]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19732]: http_auth: status=0   scheme=''   creds='Basic <response>'
1853181/http[19732]: http_auth: find client scheme
1853181/http[19732]: http_auth: found matching scheme: Basic
[127.0.0.1] cassandane Basic User logged in SESSIONID=<1853181-19732-1499107998-1-43963842423106906>
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA foreign_keys = ON;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA secure_delete = OFF;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA user_version;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): BEGIN IMMEDIATE;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA user_version;
1853181/http[19732]: creating sql_db /builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): CREATE TABLE IF NOT EXISTS ical_objs ( rowid INTEGER PRIMARY KEY, creationdate INTEGER, mailbox TEXT NOT NULL, resource TEXT NOT NULL, imap_uid INTEGER, modseq INTEGER, lock_token TEXT, lock_owner TEXT, lock_ownerid TEXT, lock_expire INTEGER, comp_type INTEGER, ical_uid TEXT, organizer TEXT, dtstart TEXT, dtend TEXT, comp_flags INTEGER, sched_tag TEXT, alive INTEGER, UNIQUE( mailbox, resource ) );
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): CREATE INDEX IF NOT EXISTS idx_ical_uid ON ical_objs ( ical_uid );
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): CREATE TABLE IF NOT EXISTS vcard_objs ( rowid INTEGER PRIMARY KEY, creationdate INTEGER, mailbox TEXT NOT NULL, resource TEXT NOT NULL, imap_uid INTEGER, modseq INTEGER, lock_token TEXT, lock_owner TEXT, lock_ownerid TEXT, lock_expire INTEGER, version INTEGER, vcard_uid TEXT, kind INTEGER, fullname TEXT, name TEXT, nickname TEXT, alive INTEGER, UNIQUE( mailbox, resource ) );
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): CREATE INDEX IF NOT EXISTS idx_vcard_fn ON vcard_objs ( fullname );
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): CREATE INDEX IF NOT EXISTS idx_vcard_uid ON vcard_objs ( vcard_uid );
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): CREATE TABLE IF NOT EXISTS vcard_emails ( rowid INTEGER PRIMARY KEY, objid INTEGER, pos INTEGER NOT NULL, email TEXT NOT NULL COLLATE NOCASE, ispref INTEGER NOT NULL DEFAULT 0, FOREIGN KEY (objid) REFERENCES vcard_objs (rowid) ON DELETE CASCADE );
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): CREATE INDEX IF NOT EXISTS idx_vcard_email ON vcard_emails ( email COLLATE NOCASE );
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): CREATE TABLE IF NOT EXISTS vcard_groups ( rowid INTEGER PRIMARY KEY, objid INTEGER, pos INTEGER NOT NULL, member_uid TEXT NOT NULL, otheruser TEXT NOT NULL DEFAULT "", FOREIGN KEY (objid) REFERENCES vcard_objs (rowid) ON DELETE CASCADE );
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): CREATE TABLE IF NOT EXISTS dav_objs ( rowid INTEGER PRIMARY KEY, creationdate INTEGER, mailbox TEXT NOT NULL, resource TEXT NOT NULL, imap_uid INTEGER, modseq INTEGER, lock_token TEXT, lock_owner TEXT, lock_ownerid TEXT, lock_expire INTEGER, filename TEXT, type TEXT, subtype TEXT, res_uid TEXT, ref_count INTEGER, alive INTEGER, UNIQUE( mailbox, resource ) );
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): CREATE INDEX IF NOT EXISTS idx_res_uid ON dav_objs ( res_uid );
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA user_version = 6;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): COMMIT;
1853181/http[19732]: auditlog: create sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars> uniqueid=<d8c9ba42-8afb-4f1d-b25f-959345af09db> uidvalidity=<1499108000>
1853181/http[19732]: auditlog: acl sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars> uniqueid=<d8c9ba42-8afb-4f1d-b25f-959345af09db> oldacl=<cassandane        lrswipkxtecdan        admin        lrswipkxtecdan        anyone        p        > acl=<cassandane        lrswipkxtecdan9        admin        lrswipkxtecdan        anyone        p        >
1853181/http[19732]: NOTIFY: response OK to method pusher
1853181/http[19732]: auditlog: modseq sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars> uniqueid=<d8c9ba42-8afb-4f1d-b25f-959345af09db> highestmodseq=<5>
1853181/http[19732]: auditlog: acl sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars> uniqueid=<d8c9ba42-8afb-4f1d-b25f-959345af09db> oldacl=<cassandane        lrswipkxtecdan9        admin        lrswipkxtecdan        anyone        p        > acl=<cassandane        lrswipkxtecdan9        admin        lrswipkxtecdan        anyone        9        >
1853181/http[19732]: NOTIFY: response OK to method pusher
1853181/http[19732]: auditlog: modseq sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars> uniqueid=<d8c9ba42-8afb-4f1d-b25f-959345af09db> highestmodseq=<6>
1853181/http[19732]: auditlog: create sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Default> uniqueid=<9fe838b8-c556-483b-a528-3299aa1375f4> uidvalidity=<1499108001>
1853181/http[19732]: auditlog: modseq sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Default> uniqueid=<9fe838b8-c556-483b-a528-3299aa1375f4> highestmodseq=<8>
1853181/http[19732]: NOTIFY: response OK to method pusher
1853181/http[19732]: NOTIFY: response OK to method pusher
1853181/http[19732]: auditlog: create sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Inbox> uniqueid=<244d00f9-bd2b-4faa-974a-82487b6ace92> uidvalidity=<1499108002>
1853181/http[19732]: auditlog: acl sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Inbox> uniqueid=<244d00f9-bd2b-4faa-974a-82487b6ace92> oldacl=<cassandane        lrswipkxtecdan9        admin        lrswipkxtecdan        anyone        9        > acl=<cassandane        lrswipkxtecdan789        admin        lrswipkxtecdan        anyone        9        >
1853181/http[19732]: NOTIFY: response OK to method pusher
1853181/http[19732]: auditlog: modseq sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Inbox> uniqueid=<244d00f9-bd2b-4faa-974a-82487b6ace92> highestmodseq=<10>
1853181/http[19732]: auditlog: acl sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Inbox> uniqueid=<244d00f9-bd2b-4faa-974a-82487b6ace92> oldacl=<cassandane        lrswipkxtecdan789        admin        lrswipkxtecdan        anyone        9        > acl=<cassandane        lrswipkxtecdan789        admin        lrswipkxtecdan        anyone        789        >
1853181/http[19732]: NOTIFY: response OK to method pusher
1853181/http[19732]: auditlog: modseq sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Inbox> uniqueid=<244d00f9-bd2b-4faa-974a-82487b6ace92> highestmodseq=<11>
1853181/http[19732]: auditlog: create sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Outbox> uniqueid=<14cb8383-76a2-4d17-8a41-584ed9097380> uidvalidity=<1499108003>
1853181/http[19732]: auditlog: acl sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Outbox> uniqueid=<14cb8383-76a2-4d17-8a41-584ed9097380> oldacl=<cassandane        lrswipkxtecdan9        admin        lrswipkxtecdan        anyone        9        > acl=<cassandane        lrswipkxtecdan789        admin        lrswipkxtecdan        anyone        9        >
1853181/http[19732]: NOTIFY: response OK to method pusher
1853181/http[19732]: auditlog: modseq sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Outbox> uniqueid=<14cb8383-76a2-4d17-8a41-584ed9097380> highestmodseq=<13>
1853181/http[19732]: auditlog: create sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Attachments> uniqueid=<cc2f5e7b-c3bd-4167-aa3a-665dc3dccf87> uidvalidity=<1499108004>
1853181/http[19732]: auditlog: acl sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Attachments> uniqueid=<cc2f5e7b-c3bd-4167-aa3a-665dc3dccf87> oldacl=<cassandane        lrswipkxtecdan9        admin        lrswipkxtecdan        anyone        9        > acl=<cassandane        lrswipkxtecdan        admin        lrswipkxtecdan        anyone        9        >
1853181/http[19732]: NOTIFY: response OK to method pusher
1853181/http[19732]: auditlog: modseq sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Attachments> uniqueid=<cc2f5e7b-c3bd-4167-aa3a-665dc3dccf87> highestmodseq=<15>
1853181/http[19732]: auditlog: acl sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Attachments> uniqueid=<cc2f5e7b-c3bd-4167-aa3a-665dc3dccf87> oldacl=<cassandane        lrswipkxtecdan        admin        lrswipkxtecdan        anyone        9        > acl=<cassandane        lrswipkxtecdan        admin        lrswipkxtecdan        anyone        r        >
1853181/http[19732]: NOTIFY: response OK to method pusher
1853181/http[19732]: auditlog: modseq sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#calendars.Attachments> uniqueid=<cc2f5e7b-c3bd-4167-aa3a-665dc3dccf87> highestmodseq=<16>
1853181/http[19732]: auditlog: create sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#addressbooks> uniqueid=<ff5263fc-8cb6-4fc1-a1fe-7a1788067c5d> uidvalidity=<1499108005>
1853181/http[19732]: auditlog: create sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#addressbooks.Default> uniqueid=<9dad5b74-d01c-47d0-82d8-d6c9e6ce163d> uidvalidity=<1499108006>
1853181/http[19732]: auditlog: modseq sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#addressbooks.Default> uniqueid=<9dad5b74-d01c-47d0-82d8-d6c9e6ce163d> highestmodseq=<19>
1853181/http[19732]: auditlog: create sessionid=<1853181-19732-1499107998-1-43963842423106906> mailbox=<user.cassandane.#notifications> uniqueid=<f86fc0f1-859d-41aa-9f70-5a0b0b6713d3> uidvalidity=<1499108007>
1853181/http[19732]: read_body(flags=0x8, framing=2)
1853181/http[19732]: write_body(code = -1964266958, flags.te = 0, len = 474)
1853181/http[19732]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19732]: simple_hdr(Connection: Upgrade)
1853181/http[19732]: simple_hdr(Upgrade: h2c)
1853181/http[19732]: simple_hdr(Vary: Accept-Encoding, Brief, Prefer)
1853181/http[19732]: simple_hdr(Content-Type: application/xml; charset=utf-8)
1853181/http[19732]: simple_hdr(Content-Length: 474)
[127.0.0.1] as "cassandane" with "Net-DAVTalk/0.01"; "PROPFIND /dav/addressbooks HTTP/1.1" (type=prop; depth=0) => "HTTP/1.1 207 Multi-Status"
1853181/http[19732]: read_body(flags=0x38, framing=2)
1853181/http[19732]: read & parse request-line
1853181/http[19732]: auditlog: traffic sessionid=<1853181-19732-1499107998-1-43963842423106906> bytes_in=<747> bytes_out=<878>
1853181/http[19732]: accepted connection
1853181/http[19732]: read & parse request-line
1853181/http[19732]: read & parse headers
1853181/http[19732]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19732]: http_auth: status=0   scheme=''   creds='Basic <response>'
1853181/http[19732]: http_auth: find client scheme
1853181/http[19732]: http_auth: found matching scheme: Basic
[127.0.0.1] cassandane Basic User logged in SESSIONID=<1853181-19732-1499107998-3-17250776162895466034>
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA foreign_keys = ON;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA secure_delete = OFF;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA user_version;
1853181/http[19732]: read_body(flags=0x8, framing=2)
1853181/http[19732]: write_body(code = -1964266958, flags.te = 0, len = 486)
1853181/http[19732]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19732]: simple_hdr(Connection: Upgrade)
1853181/http[19732]: simple_hdr(Upgrade: h2c)
1853181/http[19732]: simple_hdr(Vary: Accept-Encoding, Brief, Prefer)
1853181/http[19732]: simple_hdr(Content-Type: application/xml; charset=utf-8)
1853181/http[19732]: simple_hdr(Content-Length: 486)
[127.0.0.1] as "cassandane" with "Net-DAVTalk/0.01"; "PROPFIND /dav/principals/user/cassandane HTTP/1.1" (type=prop; depth=0) => "HTTP/1.1 207 Multi-Status"
1853181/http[19732]: read_body(flags=0x38, framing=2)
1853181/http[19732]: read & parse request-line
1853181/http[19732]: auditlog: traffic sessionid=<1853181-19732-1499107998-3-17250776162895466034> bytes_in=<384> bytes_out=<692>
1853181/http[19732]: accepted connection
1853181/http[19732]: read & parse request-line
1853181/http[19732]: read & parse headers
1853181/http[19732]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19732]: write_body(code = -1964266999, flags.te = 0, len = 0)
1853181/http[19732]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19732]: simple_hdr(Connection: Upgrade)
1853181/http[19732]: simple_hdr(Upgrade: h2c)
1853181/http[19732]: simple_hdr(Location: http://127.0.0.1:9101/dav/calendars)
1853181/http[19732]: simple_hdr(Vary: Accept-Encoding)
1853181/http[19732]: simple_hdr(Content-Length: 0)
[127.0.0.1] with "Net-DAVTalk/0.01"; "PROPFIND /.well-known/caldav HTTP/1.1" (depth=0) => "HTTP/1.1 301 Moved Permanently" (location=http://127.0.0.1:9101/dav/calendars)
1853181/http[19732]: read_body(flags=0x10, framing=2)
1853181/http[19732]: read & parse request-line
1853181/http[19732]: read & parse headers
1853181/http[19732]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19732]: http_auth: status=0   scheme=''   creds='Basic <response>'
1853181/http[19732]: http_auth: find client scheme
1853181/http[19732]: http_auth: found matching scheme: Basic
[127.0.0.1] cassandane Basic User logged in SESSIONID=<1853181-19732-1499107998-5-2016442690086059419>
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA foreign_keys = ON;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA secure_delete = OFF;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA user_version;
1853181/http[19732]: read_body(flags=0x8, framing=2)
1853181/http[19732]: write_body(code = -1964266958, flags.te = 0, len = 595)
1853181/http[19732]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19732]: simple_hdr(Connection: Upgrade)
1853181/http[19732]: simple_hdr(Upgrade: h2c)
1853181/http[19732]: simple_hdr(Vary: Accept-Encoding, Brief, Prefer)
1853181/http[19732]: simple_hdr(Content-Type: application/xml; charset=utf-8)
1853181/http[19732]: simple_hdr(Content-Length: 595)
[127.0.0.1] as "cassandane" with "Net-DAVTalk/0.01"; "PROPFIND /dav/calendars HTTP/1.1" (type=prop; depth=0) => "HTTP/1.1 207 Multi-Status"
1853181/http[19732]: read_body(flags=0x38, framing=2)
1853181/http[19732]: read & parse request-line
1853181/http[19732]: auditlog: traffic sessionid=<1853181-19732-1499107998-5-2016442690086059419> bytes_in=<991> bytes_out=<996>
1853181/http[19732]: accepted connection
1853181/http[19732]: read & parse request-line
1853181/http[19732]: read & parse headers
1853181/http[19732]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19732]: http_auth: status=0   scheme=''   creds='Basic <response>'
1853181/http[19732]: http_auth: find client scheme
1853181/http[19732]: http_auth: found matching scheme: Basic
[127.0.0.1] cassandane Basic User logged in SESSIONID=<1853181-19732-1499107998-7-15196501425957439094>
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA foreign_keys = ON;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA secure_delete = OFF;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA user_version;
1853181/http[19732]: read_body(flags=0x8, framing=2)
1853181/http[19732]: write_body(code = -1964266958, flags.te = 0, len = 601)
1853181/http[19732]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19732]: simple_hdr(Connection: Upgrade)
1853181/http[19732]: simple_hdr(Upgrade: h2c)
1853181/http[19732]: simple_hdr(Vary: Accept-Encoding, Brief, Prefer)
1853181/http[19732]: simple_hdr(Content-Type: application/xml; charset=utf-8)
1853181/http[19732]: simple_hdr(Content-Length: 601)
[127.0.0.1] as "cassandane" with "Net-DAVTalk/0.01"; "PROPFIND /dav/principals/user/cassandane HTTP/1.1" (type=prop; depth=0) => "HTTP/1.1 207 Multi-Status"
1853181/http[19732]: read_body(flags=0x38, framing=2)
1853181/http[19732]: read & parse request-line
1853181/http[19732]: auditlog: traffic sessionid=<1853181-19732-1499107998-7-15196501425957439094> bytes_in=<505> bytes_out=<807>
1853181/http[19732]: accepted connection
1853181/http[19732]: read & parse request-line
1853181/http[19732]: read & parse headers
1853181/http[19732]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19732]: http_auth: status=0   scheme=''   creds='Basic <response>'
1853181/http[19732]: http_auth: find client scheme
1853181/http[19732]: http_auth: found matching scheme: Basic
[127.0.0.1] cassandane Basic User logged in SESSIONID=<1853181-19732-1499107998-9-1620985656458913054>
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA foreign_keys = ON;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA secure_delete = OFF;
1853181/http[19732]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA user_version;
1853181/http[19732]: read_body(flags=0x8, framing=2)
1853181/http[19732]: write_body(code = -1964266958, flags.te = 0, len = 663)
1853181/http[19732]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19732]: simple_hdr(Connection: Upgrade)
1853181/http[19732]: simple_hdr(Upgrade: h2c)
1853181/http[19732]: simple_hdr(Vary: Accept-Encoding, Brief, Prefer)
1853181/http[19732]: simple_hdr(Content-Type: application/xml; charset=utf-8)
1853181/http[19732]: simple_hdr(Content-Length: 663)
[127.0.0.1] as "cassandane" with "Net-DAVTalk/0.01"; "PROPFIND /dav/principals/user/cassandane HTTP/1.1" (type=prop; depth=0) => "HTTP/1.1 207 Multi-Status"
1853181/http[19732]: read_body(flags=0x38, framing=2)
1853181/http[19732]: read & parse request-line
1853181/http[19732]: read & parse headers
1853181/http[19732]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19732]: reauth - reinit
1853181/http[19732]: http_auth: status=0   scheme=''   creds='Basic <response>'
1853181/http[19732]: http_auth: find client scheme
1853181/http[19732]: http_auth: found matching scheme: Basic
[127.0.0.1] cassandane Basic User logged in SESSIONID=<1853181-19732-1499107998-9-1620985656458913054>
1853181/http[19732]: read_body(flags=0x8, framing=2)
1853181/http[19732]: write_body(code = -1964266958, flags.te = 0, len = 545)
1853181/http[19732]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19732]: simple_hdr(Connection: Upgrade)
1853181/http[19732]: simple_hdr(Upgrade: h2c)
1853181/http[19732]: simple_hdr(Cache-Control: no-cache)
1853181/http[19732]: simple_hdr(Content-Type: application/xml; charset=utf-8)
1853181/http[19732]: simple_hdr(Content-Length: 545)
[127.0.0.1] as "cassandane" with "Net-DAVTalk/0.01"; "PROPPATCH /dav/calendars/user/cassandane HTTP/1.1" => "HTTP/1.1 207 Multi-Status"
1853181/http[19732]: auditlog: modseq sessionid=<1853181-19732-1499107998-9-1620985656458913054> mailbox=<user.cassandane.#calendars> uniqueid=<d8c9ba42-8afb-4f1d-b25f-959345af09db> highestmodseq=<22>
1853181/http[19732]: read_body(flags=0x38, framing=2)
1853181/master[19733]: about to exec /builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/libexec/cyrus-imapd/httpd
1853181/http[19733]: SQL backend defaulting to engine 'pgsql'
1853181/http[19733]: executed
1853181/http[19733]: accepted connection
1853181/http[19733]: read & parse request-line
1853181/http[19733]: read & parse headers
1853181/http[19733]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19733]: read_body(flags=0x8, framing=2)
1853181/http[19733]: write_body(code = -1964267006, flags.te = 0, len = 142)
1853181/http[19733]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19733]: simple_hdr(Connection: Upgrade)
1853181/http[19733]: simple_hdr(Upgrade: h2c)
1853181/http[19733]: simple_hdr(Vary: Accept-Encoding)
1853181/http[19733]: simple_hdr(Content-Type: application/json; charset=utf-8)
1853181/http[19733]: simple_hdr(Content-Length: 142)
[127.0.0.1] with "Net-JMAPTalk/0.07"; "POST /jmap/auth/ HTTP/1.1" => "HTTP/1.1 200 OK"
1853181/http[19733]: read_body(flags=0x38, framing=2)
1853181/http[19733]: read & parse request-line
1853181/http[19733]: read & parse headers
1853181/http[19733]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19733]: read_body(flags=0x8, framing=2)
1853181/http[19733]: write_body(code = -1964267005, flags.te = 0, len = 324)
1853181/http[19733]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19733]: simple_hdr(Connection: Upgrade)
1853181/http[19733]: simple_hdr(Upgrade: h2c)
1853181/http[19733]: simple_hdr(Vary: Accept-Encoding)
1853181/http[19733]: simple_hdr(Content-Type: application/json; charset=utf-8)
1853181/http[19733]: simple_hdr(Content-Length: 324)
[127.0.0.1] with "Net-JMAPTalk/0.07"; "POST /jmap/auth/ HTTP/1.1" => "HTTP/1.1 201 Created"
1853181/http[19733]: read_body(flags=0x38, framing=2)
1853181/http[19733]: read & parse request-line
1853181/http[19733]: read & parse headers
1853181/http[19733]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19733]: http_auth: status=0   scheme=''   creds='Bearer <response>'
1853181/http[19733]: http_auth: find client scheme
1853181/http[19733]: http_auth: found matching scheme: Bearer
[127.0.0.1] cassandane Bearer User logged in SESSIONID=<1853181-19733-1499107998-1-4005743557782097351>
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA foreign_keys = ON;
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA secure_delete = OFF;
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): PRAGMA user_version;
1853181/http[19733]: read_body(flags=0x8, framing=2)
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): SELECT rowid, creationdate, mailbox, resource, imap_uid,  lock_token, lock_owner, lock_ownerid, lock_expire,  comp_type, ical_uid, organizer, dtstart, dtend,  comp_flags, sched_tag, alive, modseq FROM ical_objs WHERE mailbox = 'user.cassandane.#calendars.Default' AND resource = 'fc0e8106-d040-48a1-ba15-435d33d4222a.ics';
1853181/http[19733]: created stage directory /builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/data/stage./
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): SAVEPOINT caldav;
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): SELECT rowid, creationdate, mailbox, resource, imap_uid,  lock_token, lock_owner, lock_ownerid, lock_expire,  comp_type, ical_uid, organizer, dtstart, dtend,  comp_flags, sched_tag, alive, modseq FROM ical_objs WHERE mailbox = 'user.cassandane.#calendars.Default' AND resource = 'fc0e8106-d040-48a1-ba15-435d33d4222a.ics';
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/caldav_alarm.sqlite3): PRAGMA foreign_keys = ON;
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/caldav_alarm.sqlite3): PRAGMA secure_delete = OFF;
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/caldav_alarm.sqlite3): PRAGMA user_version;
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/caldav_alarm.sqlite3): BEGIN IMMEDIATE;
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/caldav_alarm.sqlite3): PRAGMA user_version;
1853181/http[19733]: creating sql_db /builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/caldav_alarm.sqlite3
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/caldav_alarm.sqlite3): CREATE TABLE IF NOT EXISTS events ( mboxname TEXT NOT NULL, imap_uid INTEGER NOT NULL, nextcheck INTEGER NOT NULL, PRIMARY KEY (mboxname, imap_uid));
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/caldav_alarm.sqlite3): CREATE INDEX IF NOT EXISTS checktime ON events (nextcheck);
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/caldav_alarm.sqlite3): PRAGMA user_version = 2;
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/caldav_alarm.sqlite3): COMMIT;
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/caldav_alarm.sqlite3): DELETE FROM events WHERE mboxname = 'user.cassandane.#calendars.Default'   AND imap_uid = 1;
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): INSERT INTO ical_objs (  alive, mailbox, resource, creationdate, imap_uid, modseq,  lock_token, lock_owner, lock_ownerid, lock_expire,  comp_type, ical_uid, organizer, dtstart, dtend,  comp_flags, sched_tag ) VALUES (  1, 'user.cassandane.#calendars.Default', 'fc0e8106-d040-48a1-ba15-435d33d4222a.ics', 1499107998, 1, 23,  NULL, NULL, NULL, 0,  1, 'fc0e8106-d040-48a1-ba15-435d33d4222a', NULL, '20151107T090000Z', '20151107T110000Z',  0, NULL );
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): RELEASE SAVEPOINT caldav;
1853181/http[19733]: auditlog: append sessionid=<1853181-19733-1499107998-1-4005743557782097351> mailbox=<user.cassandane.#calendars.Default> uniqueid=<9fe838b8-c556-483b-a528-3299aa1375f4> uid=<1> modseq=<23> sysflags=<0> guid=<ae09de504fda6f312544a6f6d72e81d60dedafda>
1853181/http[19733]: auditlog: modseq sessionid=<1853181-19733-1499107998-1-4005743557782097351> mailbox=<user.cassandane.#calendars.Default> uniqueid=<9fe838b8-c556-483b-a528-3299aa1375f4> highestmodseq=<23>
1853181/http[19733]: NOTIFY: response OK to method pusher
1853181/http[19733]: write_body(code = -1964267006, flags.te = 0, len = 246)
1853181/http[19733]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19733]: simple_hdr(Connection: Upgrade)
1853181/http[19733]: simple_hdr(Upgrade: h2c)
1853181/http[19733]: simple_hdr(Vary: Accept-Encoding)
1853181/http[19733]: simple_hdr(Content-Type: application/json; charset=utf-8)
1853181/http[19733]: simple_hdr(Content-Length: 246)
[127.0.0.1] as "cassandane" with "Net-JMAPTalk/0.07"; "POST /jmap/ HTTP/1.1" => "HTTP/1.1 200 OK"
1853181/http[19733]: read_body(flags=0x38, framing=2)
1853181/http[19733]: read & parse request-line
1853181/http[19733]: read & parse headers
1853181/http[19733]: conn flags: 0  upgrade flags: 0  tls req: 0
1853181/http[19733]: reauth - reinit
1853181/http[19733]: http_auth: status=0   scheme=''   creds='Bearer <response>'
1853181/http[19733]: http_auth: find client scheme
1853181/http[19733]: http_auth: found matching scheme: Bearer
[127.0.0.1] cassandane Bearer User logged in SESSIONID=<1853181-19733-1499107998-1-4005743557782097351>
1853181/http[19733]: read_body(flags=0x8, framing=2)
1853181/http[19733]: sqldb_exec(/builddir/build/BUILD/cyrus-imapd-3.0.2/cassandane/work/1853181/conf/user/c/cassandane.dav): SELECT rowid, creationdate, mailbox, resource, imap_uid,  lock_token, lock_owner, lock_ownerid, lock_expire,  comp_type, ical_uid, organizer, dtstart, dtend,  comp_flags, sched_tag, alive, modseq FROM ical_objs WHERE alive = 1 AND ical_uid = 'fc0e8106-d040-48a1-ba15-435d33d4222a' ORDER BY mailbox, imap_uid;
1853181/http[19733]: write_body(code = -1964267006, flags.te = 0, len = 1945)
1853181/http[19733]: simple_hdr(Date: Mon, 03 Jul 2017 18:53:18 GMT)
1853181/http[19733]: simple_hdr(Connection: Upgrade)
1853181/http[19733]: simple_hdr(Upgrade: h2c)
1853181/http[19733]: simple_hdr(Vary: Accept-Encoding)
1853181/http[19733]: simple_hdr(Content-Type: application/json; charset=utf-8)
1853181/http[19733]: simple_hdr(Content-Length: 1945)
[127.0.0.1] as "cassandane" with "Net-JMAPTalk/0.07"; "POST /jmap/ HTTP/1.1" => "HTTP/1.1 200 OK"
1853181/http[19733]: read_body(flags=0x38, framing=2)
1853181/master[19725]: attempting clean shutdown on signal
1853181/http[19733]: graceful shutdown
1853181/http[19732]: graceful shutdown
1853181/imap[19731]: graceful shutdown
1853181/imap[19731]: auditlog: traffic sessionid=<1853181-19731-1499107998-1-1786010344523871877> bytes_in=<0> bytes_out=<0>
1853181/http[19732]: auditlog: traffic sessionid=<1853181-19732-1499107998-9-1620985656458913054> bytes_in=<1157> bytes_out=<1607>
1853181/http[19733]: auditlog: traffic sessionid=<1853181-19733-1499107998-1-4005743557782097351> bytes_in=<1676> bytes_out=<3391>
1853181/master[19725]: process type:SERVICE name:http path:/builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/libexec/cyrus-imapd/httpd age:0.380s pid:19732 exited, status 75
1853181/master[19725]: process type:SERVICE name:imap path:/builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/libexec/cyrus-imapd/imapd age:0.410s pid:19731 exited, status 75
1853181/master[19725]: process type:SERVICE name:http path:/builddir/build/BUILDROOT/cyrus-imapd-3.0.2-5.fc27.x86_64/usr/libexec/cyrus-imapd/httpd age:0.218s pid:19733 exited, status 75
1853181/master[19725]: All children have exited, closing down
rsto commented 7 years ago

That's because the libical library in your Fedora mock image doesn't include the Boolean value patch from September, 2016: https://github.com/libical/libical/commit/877cefda414d56b1d029e275da4840467dba2626

I rebuilt Cyrus with libical current master in a custom installation directory, and the test passed.

Unfortunately, libical's latest stable version is 2.0, which doesn't include the patch yet. From what I understand, 2.1 is coming soon, and luckily one of libical's core maintainers is also core maintainer for cyrus-imapd. If you require a stable version to package Cyrus with, we might check with @ksmurchison on the release plans.

jasontibbitts commented 7 years ago

Oh, hmm, I had asked on the IRC channel and was told that 2.0 was just fine. I know there's a configure warning output when you're "only" running the current stable libical, but nobody could identify any breakage it would cause. I guess now we know.

As always, I'm very reluctant to use a bundled libical as then I'd be responsible for worrying about libical security issues as well. But I guess I may have to do that if I want a RHEL package anyway, as RHEL7 only has libical 1.0.1.

elliefm commented 5 years ago

I guess this isn't a problem anymore, since JMAP is gone from 3.0 and libical 2.0 is old news