JMAP Email/changes doesn't report destroyed draft item if is called from a second session

[zvasilev]

Hello,

I'm write a test with two virtual clients.
Client 1 save a new draft.
Client 2 load draft and verify the draft email.
Client 1 re-save the draft with "Email/set" with "create" and "destroy" properties.

Client request
{"methodCalls":[["Email/set",{"accountId":"u606140f3","create":{"81b15d79-332c-c983-7787-ec50917d1e81":{"bcc":[],"bodyStructure":{"subParts":[{"subParts":[{"partId":"81b15d79-332c-c983-7787-ec50917d1e81-2","type":"text/plain"},{"partId":"81b15d79-332c-c983-7787-ec50917d1e81-1","type":"text/html"}],"type":"multipart/alternative"},{"blobId":"Gc93a39bc93dae76eaebe9c2be055d9f051e296f7","disposition":"attachment","name":"another attachment.txt","type":"text/plain"}],"type":"multipart/mixed"},"bodyValues":{"81b15d79-332c-c983-7787-ec50917d1e81-1":{"isTruncated":false,"value":"

test email

<a href=3D"https://www.mailtemi.com">Mailtemi! "},"81b15d79-332c-c983-7787-ec50917d1e81-2":{"isTruncated":false,"value":"test email"}},"cc":[],"from":[{"email":"zhivko@mailtemi.com","name":"zhivko@mailtemi.com"}],"keywords":{"$draft":true,"$seen":true},"mailboxIds":{"9d681aa1-7a95-44ce-b30d-d3025690fc93":true},"receivedAt":"2020-08-23T14:18:09Z","subject":"[messages_a] 1","to":[{"email":"test_sender@mailtemi.com","name":"test_sender@mailtemi.com"},{"email":"another_recipient@mailtemi.com"}]}},"destroy":["M43a5cd3c10c89026ba36b062"]},"76yyQA==#11"]],"using":["urn:ietf:params:jmap:core","urn:ietf:params:jmap:mail","urn:ietf:params:jmap:submission"]}

Server Response
{"methodResponses":[["Email/set",{"created":{"81b15d79-332c-c983-7787-ec50917d1e81":{"blobId":"G1ab9d21191cacfddd2da4577498f07439e2ac683","threadId":"T8b4a0bf09aa3c4cf","size":1075,"id":"M1ab9d21191cacfddd2da4577"}},"accountId":"u606140f3","destroyed":["M43a5cd3c10c89026ba36b062"],"oldState":"27185","updated":null,"notDestroyed":null,"notCreated":null,"newState":"27188","notUpdated":null},"76yyQA==#11"]],"sessionState":"cyrus-8825;p-5;vfs-0"}

here "destroyed":["M43a5cd3c10c89026ba36b062"] has "newState":"27188"

Client 2 load draft and verify the draft email.
"Email/changes" doesn't report deleted item, it returns only the created one.

Client request
{"methodCalls":[["Mailbox/changes",{"accountId":"u606140f3","sinceState":"27181"},"dboh1Q==#4"],["Mailbox/get",{"#ids":{"name":"Mailbox/changes","path":"/updated","resultOf":"dboh1Q==#4"},"#properties":{"name":"Mailbox/changes","path":"/updatedProperties","resultOf":"dboh1Q==#4"},"accountId":"u606140f3"},"dboh1Q==#5"],["Email/changes",{"accountId":"u606140f3","maxChanges":2,"sinceState":"27181"},"dboh1Q==#6"],["Email/get",{"#ids":{"name":"Email/changes","path":"/updated","resultOf":"dboh1Q==#6"},"accountId":"u606140f3","bodyProperties":["partId","blobId","size","name","type","disposition","cid","header:Content-Type"],"properties":["from","to","cc","bcc","threadId","receivedAt","subject","keywords","mailboxIds","textBody","htmlBody","attachments"]},"dboh1Q==#7"],["Email/get",{"#ids":{"name":"Email/changes","path":"/created","resultOf":"dboh1Q==#6"},"accountId":"u606140f3","bodyProperties":["partId","blobId","size","name","type","disposition","cid","header:Content-Type"],"properties":["from","to","cc","bcc","threadId","receivedAt","subject","keywords","mailboxIds","textBody","htmlBody","attachments"]},"dboh1Q==#8"]],"using":["urn:ietf:params:jmap:core","urn:ietf:params:jmap:mail","urn:ietf:params:jmap:submission"]}

Server response
{"sessionState":"cyrus-8825;p-5;vfs-0","methodResponses":[["Mailbox/changes",{"accountId":"u606140f3","updated":["9d681aa1-7a95-44ce-b30d-d3025690fc93"],"oldState":"27181","destroyed":[],"created":[],"hasMoreChanges":false,"newState":"27188","updatedProperties":["totalEmails","unreadEmails","totalThreads","unreadThreads"]},"dboh1Q==#4"],["Mailbox/get",{"state":"27188","accountId":"u606140f3","list":[{"totalEmails":1,"id":"9d681aa1-7a95-44ce-b30d-d3025690fc93","unreadThreads":0,"unreadEmails":0,"totalThreads":1}],"notFound":[]},"dboh1Q==#5"],["Email/changes",{"hasMoreChanges":false,"newState":"27188","accountId":"u606140f3","updated":[],"oldState":"27181","destroyed":[],"created":["M1ab9d21191cacfddd2da4577"]},"dboh1Q==#6"],["Email/get",{"list":[],"notFound":[],"accountId":"u606140f3","state":"27188"},"dboh1Q==#7"],["Email/get",{"accountId":"u606140f3","list":[{"cc":null,"to":[{"name":"test_sender@mailtemi.com","email":"test_sender@mailtemi.com"},{"email":"another_recipient@mailtemi.com","name":null}],"keywords":{"$draft":true,"$hasattachment":true,"$x-me-annot-2":true,"$seen":true},"attachments":[{"name":"another attachment.txt","partId":"2","size":12,"type":"text/plain","blobId":"Gc93a39bc93dae76eaebe9c2be055d9f051e296f7","cid":null,"disposition":"attachment","header:Content-Type":" text/plain; name="another attachment.txt""}],"threadId":"T8b4a0bf09aa3c4cf","bcc":null,"subject":"[messages_a] 1","receivedAt":"2020-08-23T14:18:09Z","mailboxIds":{"9d681aa1-7a95-44ce-b30d-d3025690fc93":true},"from":[{"email":"zhivko@mailtemi.com","name":"zhivko@mailtemi.com"}],"htmlBody":[{"name":null,"partId":"1.2","size":68,"blobId":"G5ba79357569a94d3a4ebe2a49f48388dcfb0bd9b","type":"text/html","cid":null,"disposition":null,"header:Content-Type":" text/html"}],"textBody":[{"header:Content-Type":" text/plain","disposition":null,"cid":null,"type":"text/plain","blobId":"G7152be6569b3be28da8c2af1362f48c72c058540","size":10,"partId":"1.1","name":null}],"id":"M1ab9d21191cacfddd2da4577"}],"notFound":[],"state":"27188"},"dboh1Q==#8"]]}

for "newState":"27188" is reported only the create item.

Regards,
Zhivko

[rsto]

Email/changes will not report email "M43a5cd3c10c89026ba36b062" as destroyed if the sinceQuery state argument is older than the state when the email got created. In other words: for the client fetching changes, it's as if that email never existed when it got both created and destroyed in the same Email/changes report window.

Here is what I think is happening according your logs:

1. Email state X-1: You create an email "M43a5cd3c10c89026ba36b062". New state is now X.
2. Email state 27185: You create an email "M1ab9d21191cacfddd2da4577" and destroy "M43a5cd3c10c89026ba36b062". New state is now 27188.
3. Email state 27188: You fetch Email/change since state 27181. Only "M1ab9d21191cacfddd2da4577" is reported as created.

This very much hints at that in step 1 you created email "M43a5cd3c10c89026ba36b062" at or after state 27181. Indeed, I could replicate this exact same behavior when I ran this locally.

Does this resolve your issue? If not, could you please share the telemetry including the one where you create the initial email?

[zvasilev]

Hello Robert,

Thank you to look at this.

It doesn't seem the case that for "client 2" the message never existed. Because that message is loaded and has a valid messageId returned by the server.
So when that message is "create/destroy"-ed by saving a draft by "client 1" that messageId should be reported to the "client 2" as destroyed.

I'll have time to check your suggestion tomorrow. Or if this issue still exists, I will try to isolate only to related JMAP call to save the entire session's requests and responses.

Thanks,
Zhivko

[rsto]

It doesn't seem the case that for "client 2" the message never existed. Because that message is loaded and has a valid messageId returned by the server.
So when that message is "create/destroy"-ed by saving a draft by "client 1" that messageId should be reported to the "client 2" as destroyed.

Yes, if the client has not only kept track of the messageId but also the email object state. And used the latest state as argument to Email/changes. Probably your implementation does that, and there is indeed a Cyrus bug! I just want to rule out the low-hanging fruits first.

I'll have time to check your suggestion tomorrow. Or if this issue still exists, I will try to isolate only to related JMAP call to save the entire session's requests and responses.

Yes, that would be great.

[zvasilev]

Hello Robert,

I think the bug exists.
The "app one" create/destroy a "draft" is done in a single mutation from 27819-> 27822 state returned by the server.

The "app two" asks for changes since 27815 state, but only the created is reported.

I've generated two separate JMAP passwords to be sure everything is separated.

Here are the JMAP sessions from my test.
app_1.txt
app_2.txt

[rsto]

The "app one" create/destroy a "draft" is done in a single mutation from 27819-> 27822 state returned by the server.
The "app two" asks for changes since 27815 state, but only the created is reported.

That's by design, see the spec for Foo/changes): "If a record has been created AND destroyed since the old state, the server SHOULD remove the id from the response entirely."
Since the message got created at state 27819 and destroyed before the current state 27822, there is no need to report it all when you fetch changes since 27815.

Looking at the telemetry I think the issue you are facing is that client 2 actually fetches the copy of the to-destroyed message with an Email/query. If you want to track changes of the emails you fetch in a query, you might want to use Email/queryChanges with the queryState returned by Email/query. This will report you all changes in the emails that matched the query.

[zvasilev]

Hi,

Yes, queryChanges returns removed messageId. I'll re-work my sync algorithm.

A bit more help, please.
Does the queryState an ephemeral value in the server query? The RFC sound it is, but Cyrus seems to make a search based on IMAP Modsec?

So it is valid only after Email/query call during the active session?
It is not good advice to be reused after the app restart?

[rsto]

Great! You can keep using queryState after restarts. But your code should be prepared to handle cannotCalculateChanges errors, which might occur if the query state is really old. It must handle these errors anyway, since queryChanges only supports the subset of queries that do not query on mutable properties.

[zvasilev]

Thank you for the help!