Page MenuHome GnuPG

GpgOL: Shown attachments duplicate on selection of signed emails
Closed, ResolvedPublic

Description

As seen in the Video when an signed email with attachments (send via KMail) is received the signature gets validated and all looks ok.
But if the email is deselected and then selected again it is revalided and after the validation message disappears the attachments are added to the email again.
So after N selection you end up with N versions of the attachments in the List.
These changes are seam to be written back to the server, as when you restart Outlook or connect from a different PC you see the emails with all those attachment copies.

Video of the bug

Email src:

Event Timeline

mmontkowski created this object with edit policy "Administrators".
aheinecke added a subscriber: aheinecke.

I cannot reproduce the duplication, there are probably errors in your log regarding that close / discard changes failed or something like that in this case as we leave the original message intact and only add the extracted mime parts as attachments and replace the body with the text mimepart. It would duplicate that when it would "reverrify" a mail that already went thorugh all this. But it is meant that while the mail exists in outlooks memory that GpgOL tracks that, too and so does not decrypt the same mail twice. What I can see is that multipart/signed without encryption is somehow parsed as S/MIME initially. This looks like some new behavior in Office 365 or recent versions of Outlook when the message class is changed to an S/MIME Message class. Which we do to get unmodified access to the MAPI structure. From the data objects looking at the mail in outlook spy:

and the log we can see that its all wrapped in an smime.p7m attachment. If you open that with OpenAttach you get the PGP/MIME Data as content of that.

6:34:22/8348/TRACE/mapihelp.cpp:mapi_get_message_content_type:3440: return
16:34:22/8348/mapihelp.cpp:change_message_class_ipm_note_smime_multipartsigned: content type is 'multipart/signed'
16:34:22/8348/TRACE/mapihelp.cpp:change_message_class_ipm_note_smime_multipartsigned:1424: return
16:34:22/8348/TRACE/mapihelp.cpp:string_to_type:1541 enter
16:34:22/8348/TRACE/mapihelp.cpp:string_to_type:1555: return
16:34:22/8348/TRACE/mapihelp.cpp:get_gpgololdmsgclass_tag:171 enter
16:34:22/8348/TRACE/mapihelp.cpp:create_gpgol_tag:118 enter
16:34:22/8348/TRACE/mapihelp.cpp:create_gpgol_tag:148: return
16:34:22/8348/TRACE/mapihelp.cpp:get_gpgololdmsgclass_tag:177: return
16:34:22/8348/mapihelp.cpp:mapi_change_message_class: saving old message class
16:34:22/8348/mapihelp.cpp:mapi_change_message_class: setting message class to `IPM.Note.GpgOL.SM.MultipartSigned'
16:34:22/8348/TRACE/mapihelp.cpp:mapi_do_save_changes:370 enter
16:34:22/8348/TRACE/mapihelp.cpp:mapi_has_last_decrypted:3449 enter
16:34:22/8348/TRACE/mapihelp.cpp:get_gpgollastdecrypted_tag:212 enter
16:34:22/8348/TRACE/mapihelp.cpp:create_gpgol_tag:118 enter
16:34:22/8348/TRACE/mapihelp.cpp:create_gpgol_tag:148: return
16:34:22/8348/TRACE/mapihelp.cpp:get_gpgollastdecrypted_tag:218: return
16:34:22/8348/TRACE/mapihelp.cpp:mapi_has_last_decrypted:3462: return
16:34:22/8348/TRACE/mapihelp.cpp:mapi_do_save_changes:418: return
16:34:22/8348/TRACE/mapihelp.cpp:mapi_change_message_class:1809: return
16:34:22/8348/TRACE/oomhelp.cpp:get_oom_message:1849 enter
16:34:22/8348/TRACE/oomhelp.cpp:get_oom_iunknown:941 enter
16:34:22/8348/oomhelp.cpp:lookup_oom_dispid:160 wchar_t alloc 32f005f8:MapiObject
16:34:22/8348/DBG_OOM/oomhelp.cpp:get_oom_iunknown:963 AddRef on 2f01ade4
16:34:22/8348/TRACE/oomhelp.cpp:get_object_name:84 enter
16:34:22/8348/TRACE/oomhelp.cpp:get_object_name:124: return
16:34:22/8348/TRACE/oomhelp.cpp:get_oom_iunknown:964: return
16:34:22/8348/TRACE/oomhelp.cpp:get_oom_message:1857: return
16:34:22/8348/TRACE/mapihelp.cpp:mapi_mark_or_create_moss_attach:3668 enter
16:34:22/8348/TRACE/mapihelp.cpp:mapi_create_attach_table:2529 enter
16:34:22/8348/TRACE/mapihelp.cpp:get_gpgolattachtype_tag:185 enter
16:34:22/8348/TRACE/mapihelp.cpp:create_gpgol_tag:118 enter
16:34:22/8348/TRACE/mapihelp.cpp:create_gpgol_tag:148: return
16:34:22/8348/TRACE/mapihelp.cpp:get_gpgolattachtype_tag:191: return
16:34:22/8348/DBG_OOM/mapihelp.cpp:mapi_create_attach_table:2551 AddRef on 2f124b68
16:34:22/8348/TRACE/oomhelp.cpp:get_object_name:84 enter
16:34:22/8348/TRACE/oomhelp.cpp:get_object_name:124: return
16:34:22/8348/mapihelp.cpp:mapi_create_attach_table: message has 1 attachments
16:34:22/8348/DBG_OOM/mapihelp.cpp:mapi_create_attach_table:2602 AddRef on 2e31bcd4
16:34:22/8348/TRACE/oomhelp.cpp:get_object_name:84 enter
16:34:22/8348/TRACE/oomhelp.cpp:get_object_name:124: return
16:34:22/8348/TRACE/mapihelp.cpp:get_attach_method:2348 enter
16:34:22/8348/TRACE/mapihelp.cpp:get_attach_method:2365: return
16:34:22/8348/TRACE/mapihelp.cpp:get_attach_filename:2379 enter
16:34:22/8348/mapihelp.cpp:get_attach_filename:2398 char utf8 alloc 08a4bef8:smime.p7m
16:34:22/8348/TRACE/mapihelp.cpp:get_attach_filename:2414: return
16:34:22/8348/TRACE/mapihelp.cpp:get_attach_mime_tag:2462 enter
16:34:22/8348/TRACE/mapihelp.cpp:get_attach_mime_tag:2494: return
16:34:22/8348/TRACE/mapihelp.cpp:get_attach_content_id:2422 enter
16:34:22/8348/TRACE/mapihelp.cpp:get_attach_content_id:2433: return
16:34:22/8348/TRACE/mapihelp.cpp:get_gpgolattachtype:2503 enter
16:34:22/8348/TRACE/mapihelp.cpp:get_gpgolattachtype:2514: return
16:34:22/8348/DBG_MEM/mapihelp.cpp:mapi_create_attach_table:2622: Object: 2e31bcd4 released ref: 0 
16:34:22/8348/mapihelp.cpp:mapi_create_attach_table: attachment info:
16:34:22/8348/	40965 mt=0 fname=`smime.p7m' ct=`multipart/signed' ct_parms=`(null)' method:1
16:34:22/8348/TRACE/mapihelp.cpp:mapi_create_attach_table:2648: return
16:34:22/8348/TRACE/mapihelp.cpp:mapi_mark_moss_attach:2841 enter
16:34:22/8348/mapihelp.cpp:mapi_mark_moss_attach: Marking 40965 as MOSS attachment
16:34:22/8348/DBG_OOM/mapihelp.cpp:mapi_mark_moss_attach:2862 AddRef on 2e31bcd4
16:34:22/8348/TRACE/oomhelp.cpp:get_object_name:84 enter
16:34:22/8348/TRACE/oomhelp.cpp:get_object_name:124: return
16:34:22/8348/DBG_MEM/memdbg.cpp:register_name Ptr 2e31bcd4 name change from mapi_create_attach_table to mapi_mark_moss_attach
16:34:22/8348/TRACE/mapihelp.cpp:get_gpgolattachtype_tag:185 enter
16:34:22/8348/TRACE/mapihelp.cpp:create_gpgol_tag:118 enter
16:34:22/8348/TRACE/mapihelp.cpp:create_gpgol_tag:148: return
16:34:22/8348/TRACE/mapihelp.cpp:get_gpgolattachtype_tag:191: return
16:34:22/8348/DBG_MEM/mapihelp.cpp:mapi_mark_moss_attach:2897: Object: 2e31bcd4 released ref: 0 
16:34:22/8348/TRACE/mapihelp.cpp:mapi_mark_moss_attach:2898: return
16:34:22/8348/TRACE/mapihelp.cpp:mapi_release_attach_table:2656 enter
16:34:22/8348/DBG_MEM/mapihelp.cpp:mapi_release_attach_table:2667: Object: 2f124b68 released ref: 0 
16:34:22/8348/TRACE/mapihelp.cpp:mapi_release_attach_table:2675: return
16:34:22/8348/TRACE/mapihelp.cpp:mapi_mark_or_create_moss_attach:3861: return
16:34:22/8348/DBG_MEM/mail.cpp:preProcessMessage_m:406: Object: 2f01ade4 released ref: 3 
16:34:22/8348/DBG_MEM/mail.cpp:preProcessMessage_m:414: Object: 2e31bc94 released ref: 3 
16:34:22/8348/TRACE/mail.cpp:preProcessMessage_m:415: return
16:34:22/8348/TRACE/mailitem-events.cpp:Invoke:243: break
16:34:22/8348/TRACE/mailitem-events.cpp:Invoke:1070: return
16:34:22/8348/TRACE/mailitem-events.cpp:Invoke:137 enter
16:34:22/8348/DBG_OOM/mailitem-events.cpp:Invoke: ReadComplete: 32eb5758

The verification happens with OpenPGP because before we do the actual verification we use gpgme_data_identify to figure out what to use. But from the outside it looks to GpgOL like an S/MIME Mail. This is also in you image why it shows the grey "please wait" for so long since it verifies the mail twice, once with an offline context and once with an online one, to show the content already in case long running crl checks are still working. But all this does not explain to me why the attachments get duplicated. I tried it easily more then 30 times, opening the mail in different windows, closing and opening really fast etc. and the state in the end was always fine.

And this is even with the "save before decrypt" code added in the last release. So I guess we now need to look at your logs around the unload / close event if something fails there.

17:04:03/5012/oomhelp.cpp:lookup_oom_dispid:160 wchar_t alloc 2cab7ed8:MessageClass
17:04:03/5012/oomhelp.cpp:put_oom_string:674 wchar_t alloc 0e4005d8:IPM.Note.SMIME.MultipartSigned
17:04:03/5012/TRACE/mailitem-events.cpp:Invoke:137 enter
17:04:03/5012/TRACE/mail.cpp:isCryptoMail:1359 enter
17:04:03/5012/TRACE/mail.cpp:isCryptoMail:1366: return
17:04:03/5012/DBG_OOM/mailitem-events.cpp:Invoke: Mail 2cabc790 propchange: MessageClass no warning.
17:04:03/5012/TRACE/mailitem-events.cpp:Invoke:332: return
17:04:03/5012/TRACE/oomhelp.cpp:put_oom_string:701: return
17:04:03/5012/mail.cpp:decryptVerify_o:Invoking save to store potential changes before decryption.
17:04:03/5012/TRACE/oomhelp.cpp:invoke_oom_method:1957 enter
17:04:03/5012/TRACE/oomhelp.cpp:invoke_oom_method:1958: return
17:04:03/5012/TRACE/oomhelp.cpp:invoke_oom_method_with_parms:1949 enter
17:04:03/5012/TRACE/oomhelp.cpp:invoke_oom_method_with_parms:1950: return
17:04:03/5012/TRACE/oomhelp.cpp:invoke_oom_method_with_parms_type:1919 enter
17:04:03/5012/oomhelp.cpp:lookup_oom_dispid:160 wchar_t alloc 2c9bffe0:Save
17:04:03/5012/TRACE/mailitem-events.cpp:Invoke:137 enter
17:04:03/5012/DBG_OOM/mailitem-events.cpp:Invoke: Write : 2cabc790
17:04:03/5012/mailitem-events.cpp:Invoke: Passing write because passNextWrite was set for 2cabc790
17:04:03/5012/TRACE/mailitem-events.cpp:Invoke:654: break
17:04:03/5012/TRACE/mailitem-events.cpp:Invoke:1070: return

Today this was reproducible for me, too. Not sure what the difference is yet to yesterday I could see in my logs that this time the mails were never completely unloaded so that might be a reason. But we cannot rely on that. So reopening mails must work of course even if the mail stays open. (Good to simulate by keeping outlook spy active on the mail when loading and unloading).

One issue here that we can split out is that verification starts out as treating the mail as an S/MIME Mail. This is new and likely related to server side changes in office 365. In this screenshot here GpgOL has never touched the mail, it was disabled when the mail was received, on the OOM level we see that it shows up like a multipart/mixed mail and at the IMapiGetSecureMessage level on the right side it is treated like an opaque signed S/MIME mail.

On the left side is the OOM/MAPI view and on the right side is the view if you use the IMAPISecureMessage interface.

I understand the problem now. The difference between my test yesterday and today was that I had disabled S/MIME support in my GpgOL. Since T7243: GpgOL: multipart/signed OpenPGP SMTP transfered mails are displayed as S/MIME is an issue that makes GpgOL think that it is looking at an S/MIME mail but S/MIME is disabled, it tries to write back the mail to the server in a way so that Outlooks internal S/MIME support can parse it on the next run. In the log you see:

10:04:18/7692/mailitem-events.cpp:Invoke: S/MIME mail but S/MIME is disabled. Need save.

This causes the state of the mail to be set to m_needs_save=true and the consequence of that are the persistent changes that we see since this causes the write event not to be canceled. Instead it tries to "revert" the mail to the Outlook format but fails since this is not an S/MIME Mail,.. The revert code has always been fragile since it is rarely used nowadays as the default has been to keep S/MIME in the hands of Outlook and when users decide to use S/MIME with GpgOL they are also not likely to want to revert their mail so that they can be read by Outlook again. But the failure handling should be improved so that the write is aborted properly as you can see in the log below GpgOL detects that something is terribly wrong. But with the failing revert and the passing save that explains the attachment duplication and general brokenness of the mail.

The revert error reads:

14:52:54/10600/DBG_OOM/oomhelp.cpp:get_oom_object: looking for 17ebf538->`Selection'
14:52:54/10600/DBG_OOM/oomhelp.cpp:get_oom_object:411 AddRef on 2c9084e8
14:52:54/10600/DBG_OOM/mailitem-events.cpp:Invoke: Write : 2472cd90
14:52:54/10600/DBG_OOM/oomhelp.cpp:get_pa_variant: Looking up property: http://schemas.microsoft.com/mapi/proptag/0x001A001F;
14:52:54/10600/DBG_OOM/oomhelp.cpp:get_oom_object: looking for 2d1b8158->`PropertyAccessor'
14:52:54/10600/DBG_OOM/oomhelp.cpp:get_oom_object:411 AddRef on 2d1b7c10
14:52:54/10600/revert.cpp:gpgol_mailitem_revert: message class is `IPM.Note.SMIME.MultipartSigned'
14:52:54/10600/ERROR/revert.cpp:gpgol_mailitem_revert: Message processed but not our class. Bug.
14:52:54/10600/ERROR/mail.cpp:revert_o: Message revert failed falling back to wipe.
14:52:54/10600/mail.cpp:wipe_o: Removing plaintext from mailitem: 2d1b8158.
14:52:54/10600/DBG_OOM/mailitem-events.cpp:Invoke: Mail 2472cd90 propchange: HTMLBody no warning.
14:52:54/10600/DBG_OOM/mailitem-events.cpp:Invoke: Mail 2472cd90 propchange: Body no warning.

This is another side effect of: dd3ff8397aaf62e58fa9405ddc5397cb6bcfdc29 and 1f9c757872b033e1be8199c4d488ac84bf8f07bd before that revision the code that changed IPM.Note.GpgOL.MultipartSigned to IPM.Note.SMIME.MultipartSigned was only executed for S/MIME mails. I do now understand that the code in question at the beginning of decryptVerify_o was meant for other Addins, Outlook Web Interface etc. to ensure that the message class on the server was always IPM.Note.SMIME and not some GpgOL specific class so that outlook or other tools like securePIM would still treat the mail as S/MIME.

Now it was enabled for both S/MIME and OpenPGP messages. And MultipartSigned is used both for S/MIME and OpenPGP in GpgOL.

Even that would have been no problem when S/MIME is enabled since we handle that and decrypt. But when S/MIME was disabled this caused GpgOL to later think that the message class needed to be left on IPM.Note.SMIME.MultipartSigned and not on a GpgOL specific class like IPM.Note.GpgOL.MultipartSigned since the message strucutre was then not what was expected this lead to errors and the broken behavior we see here.

Now a second part of that issue is that an additional check to look for "uncancellable write events" was causing automatic marking of Mails as "read" to be blocked, and we relied on this place to now set the read state manually. This caused T7223. I have now fixed it and made changes to only do this save (for non s-mime mails) if the mail is encrypted. Then the noSaveBeforeDecrypt option can also be left as is, since it will only affect that case. Since we will on the other hand allow the uncancellable write events to pass again if the mail is not currently in a decrypted state.

I have tested both S/MIME and OpenPGP signed, signed + encrypted, and for S/MIME also Opaque signed. I hope this does not have another side effect. But I still do not really understand the undocumented "uncancellable write event" from dd3ff8397aaf62e58fa9405ddc5397cb6bcfdc29 and how this behaves but falling through to close there is also the likely cause of other problems we have seen. Esp. the read -> unload -> read pattern we have seen in combination with some addins and in general more incompatibility with other addins. The added check to only cancel the event if we have a decrypt Result should solve all this as it will no longer involve all the early read code.

werner mentioned this in Unknown Object (Maniphest Task).Wed, Aug 28, 11:51 AM
ebo moved this task from Restricted Project Column to Restricted Project Column on the Restricted Project board.

Getestet, beim normalen wechseln taucht dieses Verhalten so nicht mehr auf. Aber einmalig nach Klick auf weiterleitung dafür neues Ticket T7276

mmontkowski moved this task from Restricted Project Column to Restricted Project Column on the Restricted Project board.Wed, Aug 28, 3:04 PM