{"action":"created","issue":{"url":"https://api.github.com/repos/cyrusimap/cyrus-imapd/issues/2430","repository_url":"https://api.github.com/repos/cyrusimap/cyrus-imapd","labels_url":"https://api.github.com/repos/cyrusimap/cyrus-imapd/issues/2430/labels{/name}","comments_url":"https://api.github.com/repos/cyrusimap/cyrus-imapd/issues/2430/comments","events_url":"https://api.github.com/repos/cyrusimap/cyrus-imapd/issues/2430/events","html_url":"https://github.com/cyrusimap/cyrus-imapd/issues/2430","id":339680301,"node_id":"MDU6SXNzdWUzMzk2ODAzMDE=","number":2430,"title":"JMAP: intermittent EmailSubmission issue","user":{"login":"robmueller","id":606019,"node_id":"MDQ6VXNlcjYwNjAxOQ==","avatar_url":"https://avatars3.githubusercontent.com/u/606019?v=4","gravatar_id":"","url":"https://api.github.com/users/robmueller","html_url":"https://github.com/robmueller","followers_url":"https://api.github.com/users/robmueller/followers","following_url":"https://api.github.com/users/robmueller/following{/other_user}","gists_url":"https://api.github.com/users/robmueller/gists{/gist_id}","starred_url":"https://api.github.com/users/robmueller/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/robmueller/subscriptions","organizations_url":"https://api.github.com/users/robmueller/orgs","repos_url":"https://api.github.com/users/robmueller/repos","events_url":"https://api.github.com/users/robmueller/events{/privacy}","received_events_url":"https://api.github.com/users/robmueller/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2018-07-10T03:29:41Z","updated_at":"2018-07-12T03:38:27Z","closed_at":null,"author_association":"CONTRIBUTOR","body":"Neil is able to semi-regularly reproduce an EmailSubmission error particularly with attachments. Looking at the logs, there's definitely something weird happening internally.\r\n\r\nFirst the attachment is uploaded.\r\n\r\n```\r\n2018-07-09T23:08:57.680503-04:00 imap22 sloti22d1t06/httpjmap[2580046]: login: betaweb1 [...] neilj@fastmail.fm Basic User logged in SESSIONID=<sloti22d1t06-2580046-1531192137-1-10746642633129269092>\r\n2018-07-09T23:08:57.783963-04:00 imap22 sloti22d1t06/httpjmap[2580046]: auditlog: append sessionid=<sloti22d1t06-2580046-1531192137-1-10746642633129269092> mailbox=<fastmail.fm!user.neilj.#jmap> uniqueid=<aad6769e-03fe-4cd3-a356-c801b662c21a> uid=<10> modseq=<786303> sysflags=<DE|AR|EX> guid=<1081edc992324203ccadecef2c9a5abb0b83a0dc> messageid=unknown\r\n2018-07-09T23:08:57.783971-04:00 imap22 sloti22d1t06/httpjmap[2580046]: auditlog: expunge sessionid=<sloti22d1t06-2580046-1531192137-1-10746642633129269092> mailbox=<fastmail.fm!user.neilj.#jmap> uniqueid=<aad6769e-03fe-4cd3-a356-c801b662c21a> uid=<10> modseq=<786303> sysflags=<DE|AR|EX> guid=<1081edc992324203ccadecef2c9a5abb0b83a0dc>\r\n2018-07-09T23:08:57.784451-04:00 imap22 sloti22d1t06/httpjmap[2580046]: auditlog: modseq sessionid=<sloti22d1t06-2580046-1531192137-1-10746642633129269092> mailbox=<fastmail.fm!user.neilj.#jmap> uniqueid=<aad6769e-03fe-4cd3-a356-c801b662c21a> highestmodseq=<786303>\r\n2018-07-09T23:08:57.784586-04:00 imap22 sloti22d1t06/httpjmap[2580046]: betaweb1 [...] as \"neilj@fastmail.fm\" with \"Net-JMAPTalk/0.10\"; \"POST /jmap/upload/neilj@fastmail.fm/ HTTP/1.1\" (tx-encoding=chunked; auth=Basic) => \"HTTP/1.1 201 Created\" [timing: cmd=0.104483 net=0.000345 total=0.104828]\r\n```\r\nThen the draft is created.\r\n```\r\n2018-07-09T23:08:58.098051-04:00 imap22 sloti22d1t06/httpjmap[2580030]: login: betaweb1 [...] neilj@fastmail.fm Basic User logged in SESSIONID=<sloti22d1t06-2580030-1531192138-1-2571312781315570124>\r\n2018-07-09T23:08:58.265257-04:00 imap22 sloti22d1t06/httpjmap[2580030]: auditlog: append sessionid=<sloti22d1t06-2580030-1531192138-1-2571312781315570124> mailbox=<fastmail.fm!user.neilj.Drafts> uniqueid=<7cb4e8ee-df87-4757-b9c4-2ea1ca41b38e> uid=<21221> modseq=<786304> sysflags=<AR> guid=<2b9bcacde062f9722e706636e358a8af67b405bf> messageid=<6400e982-6b8f-4335-9977-46d1a2304eb1@sloti22d1t06>\r\n2018-07-09T23:08:58.265608-04:00 imap22 sloti22d1t06/httpjmap[2580030]: auditlog: modseq sessionid=<sloti22d1t06-2580030-1531192138-1-2571312781315570124> mailbox=<fastmail.fm!user.neilj.Drafts> uniqueid=<7cb4e8ee-df87-4757-b9c4-2ea1ca41b38e> highestmodseq=<786305>\r\n2018-07-09T23:08:58.268188-04:00 imap22 sloti22d1t06/httpjmap[2580030]: auditlog: touched sessionid=<sloti22d1t06-2580030-1531192138-1-2571312781315570124> mailbox=<fastmail.fm!user.neilj.Drafts> uniqueid=<7cb4e8ee-df87-4757-b9c4-2ea1ca41b38e> uid=<21221> guid=<2b9bcacde062f9722e706636e358a8af67b405bf> cid=<ba68132ceb0bf260> modseq=<786306> oldflags=<AR> sysflags=<DR|SE|AR>\r\n2018-07-09T23:08:58.270165-04:00 imap22 sloti22d1t06/httpjmap[2580030]: auditlog: modseq sessionid=<sloti22d1t06-2580030-1531192138-1-2571312781315570124> mailbox=<fastmail.fm!user.neilj.Drafts> uniqueid=<7cb4e8ee-df87-4757-b9c4-2ea1ca41b38e> highestmodseq=<786306>\r\n2018-07-09T23:08:58.272502-04:00 imap22 sloti22d1t06/httpjmap[2580030]: betaweb1 [...] as \"neilj@fastmail.fm\" with \"Net-JMAPTalk/0.10\"; \"POST /jmap/ HTTP/1.1\" (auth=Basic; jmap=Email/set) => \"HTTP/1.1 200 OK\" [timing: cmd=0.174052 net=0.002083 total=0.176135]\r\n```\r\n And then then email is submitted.\r\n```\r\n2018-07-09T23:09:00.370918-04:00 imap22 sloti22d1t06/httpjmap[2580030]: login: betaweb1 [...] neilj@fastmail.fm Basic User logged in SESSIONID=<sloti22d1t06-2580030-1531192140-1-5518550648502111102>\r\n2018-07-09T23:09:00.372832-04:00 imap22 sloti22d1t06/httpjmap[2580030]: jmap_sendrecord: can't open /mnt/ssd22d1/sloti22d1t06/store23/spool/domain/f/fastmail.fm/n/user/neilj/Drafts/21221.: No such file or directory\r\n2018-07-09T23:09:00.380679-04:00 imap22 sloti22d1t06/httpjmap[2580030]: auditlog: append sessionid=<sloti22d1t06-2580030-1531192140-1-5518550648502111102> mailbox=<fastmail.fm!user.neilj.Sent Items> uniqueid=<73dbcb4b-bffc-48bd-8c2a-a2e91ca672f6> uid=<8392> modseq=<786307> sysflags=<DR|SE|AR> guid=<2b9bcacde062f9722e706636e358a8af67b405bf> messageid=<6400e982-6b8f-4335-9977-46d1a2304eb1@sloti22d1t06>\r\n2018-07-09T23:09:00.381014-04:00 imap22 sloti22d1t06/httpjmap[2580030]: auditlog: modseq sessionid=<sloti22d1t06-2580030-1531192140-1-5518550648502111102> mailbox=<fastmail.fm!user.neilj.Sent Items> uniqueid=<73dbcb4b-bffc-48bd-8c2a-a2e91ca672f6> highestmodseq=<786308>\r\n2018-07-09T23:09:00.384693-04:00 imap22 sloti22d1t06/httpjmap[2580030]: auditlog: touched sessionid=<sloti22d1t06-2580030-1531192140-1-5518550648502111102> mailbox=<fastmail.fm!user.neilj.Drafts> uniqueid=<7cb4e8ee-df87-4757-b9c4-2ea1ca41b38e> uid=<21221> guid=<2b9bcacde062f9722e706636e358a8af67b405bf> cid=<ba68132ceb0bf260> modseq=<786309> oldflags=<DR|SE|AR> sysflags=<DE|DR|SE|AR|EX>\r\n2018-07-09T23:09:00.387171-04:00 imap22 sloti22d1t06/httpjmap[2580030]: auditlog: expunge sessionid=<sloti22d1t06-2580030-1531192140-1-5518550648502111102> mailbox=<fastmail.fm!user.neilj.Drafts> uniqueid=<7cb4e8ee-df87-4757-b9c4-2ea1ca41b38e> uid=<21221> modseq=<786309> sysflags=<DE|DR|SE|AR|EX> guid=<2b9bcacde062f9722e706636e358a8af67b405bf>\r\n2018-07-09T23:09:00.387560-04:00 imap22 sloti22d1t06/httpjmap[2580030]: auditlog: modseq sessionid=<sloti22d1t06-2580030-1531192140-1-5518550648502111102> mailbox=<fastmail.fm!user.neilj.Drafts> uniqueid=<7cb4e8ee-df87-4757-b9c4-2ea1ca41b38e> highestmodseq=<786309>\r\n2018-07-09T23:09:00.389208-04:00 imap22 sloti22d1t06/httpjmap[2580030]: auditlog: touched sessionid=<sloti22d1t06-2580030-1531192140-1-5518550648502111102> mailbox=<fastmail.fm!user.neilj.Sent Items> uniqueid=<73dbcb4b-bffc-48bd-8c2a-a2e91ca672f6> uid=<8392> guid=<2b9bcacde062f9722e706636e358a8af67b405bf> cid=<ba68132ceb0bf260> modseq=<786310> oldflags=<DR|SE|AR> sysflags=<SE|AR>\r\n2018-07-09T23:09:00.390137-04:00 imap22 sloti22d1t06/httpjmap[2580030]: auditlog: modseq sessionid=<sloti22d1t06-2580030-1531192140-1-5518550648502111102> mailbox=<fastmail.fm!user.neilj.Sent Items> uniqueid=<73dbcb4b-bffc-48bd-8c2a-a2e91ca672f6> highestmodseq=<786310>\r\n2018-07-09T23:09:00.393584-04:00 imap22 sloti22d1t06/httpjmap[2580030]: betaweb1 [...] as \"neilj@fastmail.fm\" with \"Net-JMAPTalk/0.10\"; \"POST /jmap/ HTTP/1.1\" (auth=Basic; jmap=EmailSubmission/set) => \"HTTP/1.1 200 OK\" [timing: cmd=0.021452 net=0.002167 total=0.023619]\r\n```\r\n\r\nThe weirdest bit of this is the `2018-07-09T23:09:00.372832-04:00 imap22 sloti22d1t06/httpjmap[2580030]: jmap_sendrecord: can't open /mnt/ssd22d1/sloti22d1t06/store23/spool/domain/f/fastmail.fm/n/user/neilj/Drafts/21221.: No such file or directory` line.\r\n\r\nOh, I think I might know what's happening here. When the draft is first created it has `sysflags=<AR>`, which means it's on the archive partition, however the /mnt/ssd22d1/ path is definitely not the archive partition! So it appears the archive flag is being set, but then later when it goes to look for the message, it's looking on the non-archive partition for the file.\r\n\r\nSo a couple of things:\r\n1. Whatever code is generating the \"path to email on disk\" needs to be passed the appropriate message flags\r\n2. Is there a reason we're creating the draft on the archive partition rather than the pain one anyway?\r\n"},"comment":{"url":"https://api.github.com/repos/cyrusimap/cyrus-imapd/issues/comments/404379281","html_url":"https://github.com/cyrusimap/cyrus-imapd/issues/2430#issuecomment-404379281","issue_url":"https://api.github.com/repos/cyrusimap/cyrus-imapd/issues/2430","id":404379281,"node_id":"MDEyOklzc3VlQ29tbWVudDQwNDM3OTI4MQ==","user":{"login":"robmueller","id":606019,"node_id":"MDQ6VXNlcjYwNjAxOQ==","avatar_url":"https://avatars3.githubusercontent.com/u/606019?v=4","gravatar_id":"","url":"https://api.github.com/users/robmueller","html_url":"https://github.com/robmueller","followers_url":"https://api.github.com/users/robmueller/followers","following_url":"https://api.github.com/users/robmueller/following{/other_user}","gists_url":"https://api.github.com/users/robmueller/gists{/gist_id}","starred_url":"https://api.github.com/users/robmueller/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/robmueller/subscriptions","organizations_url":"https://api.github.com/users/robmueller/orgs","repos_url":"https://api.github.com/users/robmueller/repos","events_url":"https://api.github.com/users/robmueller/events{/privacy}","received_events_url":"https://api.github.com/users/robmueller/received_events","type":"User","site_admin":false},"created_at":"2018-07-12T03:38:27Z","updated_at":"2018-07-12T03:38:27Z","author_association":"CONTRIBUTOR","body":"That could be it. It would explain why this is only sometimes a problem."}}
{"actor":{"display_login":"robmueller"}}