Enigmail / Bugs / #595 Thunderbird with Enigmail on Windows 10 freezes after sending mail

Patrick Brunschwig - 2016-04-09

I see two possible reasons:

a pinentry dialog that is waiting for you in the background

a running gpg.exe or gpg2.exe process. If yes, what happens if you kill it?

Last edit: Patrick Brunschwig 2016-04-09
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
- Jürgen Rathlev - 2016-04-09
  
  Nothing applies to my issue:
  
  The pinentry dialog works as usual
  
  No gpg.exe or pgp2.exe process is running. The only concerning process running is gpg-agent.exe.
  
  Thunderbird is marked "inactive" in the Task Manager.
  
  Another information: Windows 10 is 64 bit, Thunderbird, etc. 32 bit
  
  On 09.04.2016 15:48, Patrick Brunschwig wrote:
  
  I see two possible reasons:
  a pinentry dialog that is waiting for you in the background
  a running gpg.exe or gpg2.exe process. If yes, what happens if you kill it?
  
  [bugs:#595] Thunderbird with Enigmail on Windows 10 freezes after sending mail
  
  Status: open
  Created: Sat Apr 09, 2016 12:05 PM UTC by Jürgen Rathlev
  Last Updated: Sat Apr 09, 2016 12:05 PM UTC
  Owner: nobody
  
  I have been using Thunderbird with Enigmail for a long time under Windows 7 and everything worked all right. After upgrading to Windows 10 without changing any Thunderbird settings the following issue arised:
  After clicking on send, the mail is sent immediately. The status window is displayed and says "Mail sent successfully". But this window remains staying on the desktop for exact 90 seconds. Meanwhile Thunderbird is blocked, the status window shows "Not responding". This will happen irrespective of having an attachment or not.
  
  If Enigmail is deactivated, everything works all right.
  
  Sent from sourceforge.net because you indicated interest in https://sourceforge.net/p/enigmail/bugs/595/
  
  To unsubscribe from further messages, please visit https://sourceforge.net/auth/subscriptions/
  
  Related
  
  Bugs: ~~#595~~
  
  If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Jürgen Rathlev - 2016-04-14

Additional information from Thunderbird smtp logs:

1: "Signing: ON"
... ()
2016-04-14 09:46:36.358000 UTC - 0[3e11140]: SMTP entering state: 0
2016-04-14 09:46:36.358000 UTC - 0[3e11140]: SMTP Response: 250 2.0.0 Ok: queued as A55A023EFE6
2016-04-14 09:46:36.358000 UTC - 0[3e11140]: SMTP entering state: 9
2016-04-14 09:46:36.358000 UTC - 0[3e11140]: SMTP Send: QUIT

2016-04-14 09:46:36.358000 UTC - 0[3e11140]: SMTP entering state: 0
2016-04-14 09:46:36.374000 UTC - 0[3e11140]: SMTP entering state: 0
2016-04-14 09:46:36.374000 UTC - 0[3e11140]: SMTP Response: 221 2.0.0 Bye
2016-04-14 09:46:36.374000 UTC - 0[3e11140]: SMTP entering state: 10
2016-04-14 09:48:05.546000 UTC - 0[3e11140]: SMTP entering state: 12
2016-04-14 09:48:05.546000 UTC - 0[3e11140]: SMTP connection error quitting 804b0002, ignoring
==> 90 s delay betweeen state: 10 and 12

2: "Signing: OFF"
...
2016-04-14 09:57:18.862000 UTC - 0[3e11140]: SMTP entering state: 0
2016-04-14 09:57:18.862000 UTC - 0[3e11140]: SMTP Response: 250 2.0.0 Ok: queued as 228BA23F42B
2016-04-14 09:57:18.862000 UTC - 0[3e11140]: SMTP entering state: 9
2016-04-14 09:57:18.862000 UTC - 0[3e11140]: SMTP Send: QUIT

2016-04-14 09:57:18.862000 UTC - 0[3e11140]: SMTP entering state: 0
2016-04-14 09:57:18.878000 UTC - 0[3e11140]: SMTP entering state: 0
2016-04-14 09:57:18.878000 UTC - 0[3e11140]: SMTP Response: 221 2.0.0 Bye
2016-04-14 09:57:18.878000 UTC - 0[3e11140]: SMTP entering state: 10
2016-04-14 09:57:18.909000 UTC - 0[3e11140]: SMTP entering state: 12
2016-04-14 09:57:18.909000 UTC - 0[3e11140]: SMTP connection error quitting 804b0002, ignoring
==> no delay

Last edit: Jürgen Rathlev 2016-04-15

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Jürgen Rathlev - 2016-04-15

relating parts of other logs ( local time = UTC+2):

enigdbug.txt
...
2016-04-14 11:46:36.386 [DEBUG] enigmailMsgComposeOverlay.js: ECSL.ComposeProcessDone: 0
2016-04-14 11:46:36.400 [DEBUG] enigmailMsgComposeOverlay.js: EDSL.enigDocStateListener.NotifyDocumentStateChanged
2016-04-14 11:46:36.401 [DEBUG] enigmailMsgComposeOverlay.js: EDSL.enigDocStateListener.NotifyDocumentStateChanged
2016-04-14 11:46:36.402 [DEBUG] enigmailMsgComposeOverlay.js: EDSL.enigDocStateListener.NotifyDocumentStateChanged
2016-04-14 11:46:36.407 [DEBUG] enigmailMsgComposeOverlay.js: EDSL.enigDocStateListener.NotifyDocumentStateChanged
2016-04-14 11:46:36.410 [DEBUG] enigmailMsgComposeOverlay.js: Enigmail.msg.msgComposeClose
2016-04-14 11:46:36.410 [DEBUG] enigmailMsgComposeOverlay.js: Enigmail.msg.msgComposeReset
2016-04-14 11:48:05.837 [DEBUG] expiry.jsm: keyExpiryCheck()
2016-04-14 11:48:05.837 [DEBUG] expiry.jsm: getNewlyExpiredKeys()
2016-04-14 11:48:05.879 [DEBUG] mimeDecrypt.js: PgpMimeHandler()
2016-04-14 11:48:05.880 [DEBUG] pgpmimeHandler.js: onStartRequest

OpenPGP.log (gnupg2-2.0.29)
...
2016-04-14 11:46:35 gpg[5572] DBG: cache_user_id: already in cache
2016-04-14 11:46:35 gpg[5572] DBG: connection to agent established
2016-04-14 11:46:36 gpg[5572] Schreiben auf die Standardausgabe
2016-04-14 11:46:36 gpg[5572] DBG: armor-filter: control: 5
2016-04-14 11:46:36 gpg[5572] DBG: armor-filter: control: 1
2016-04-14 11:46:36 gpg[5572] RSA/SHA256 Signatur von: "9A031CDE xxxxx Info info@xxxxx.de"
2016-04-14 11:46:36 gpg[5572] DBG: build_packet() type=2
2016-04-14 11:46:36 gpg[5572] DBG: armor-filter: control: 4
2016-04-14 11:46:36 gpg[5572] DBG: armor-filter: control: 2

gpg-agent.log
...
2016-04-14 11:46:35 gpg-agent[4056] Handhabungsroutine 0x2308 für fd 472 gestartet
gpg-agent[4056]: chan_0x000001d8 -> OK Pleased to meet you
gpg-agent[4056]: chan_0x000001d8 <- RESET
gpg-agent[4056]: chan_0x000001d8 -> OK
gpg-agent[4056]: chan_0x000001d8 <- OPTION allow-pinentry-notify
gpg-agent[4056]: chan_0x000001d8 -> OK
gpg-agent[4056]: chan_0x000001d8 <- AGENT_ID
gpg-agent[4056]: chan_0x000001d8 -> ERR 67109139 Unbekanntes IPC Kommando <gpg agent="">
gpg-agent[4056]: chan_0x000001d8 <- GETINFO cmd_has_option GET_PASSPHRASE repeat
gpg-agent[4056]: chan_0x000001d8 -> OK
gpg-agent[4056]: chan_0x000001d8 <- GET_PASSPHRASE --data --repeat=0 -- ....
gpg-agent[4056]: chan_0x000001d8 -> [[Confidential data not shown]]
gpg-agent[4056]: chan_0x000001d8 -> [[Confidential data not shown]]
gpg-agent[4056]: chan_0x000001d8 <- [error: Input/output error]
2016-04-14 11:46:36 gpg-agent[4056] Assuan processing failed: Input/output error
2016-04-14 11:46:36 gpg-agent[4056] Handhabungsroutine 0x2308 für den fd 472 beendet</gpg>

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Ludwig Hügelschäfer - 2016-04-16

state: 10 = SMTP_DONE
state: 12 = SMTP_FREE

The only thing happening between those is a call to "do_QueryInterface(m_runningURL);"

Patrick, is this ringing a bell for you? I'm not good at reading TB C++ code.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Patrick Brunschwig - 2016-04-16

What I can see in the two logs is that there is no activity on the side of Enigmail between 11:46:36 and 11:48:05 (which equals to 09:46 - 09:48) in the SMTP log. The gpg-logs obviously don't do anything either.

At 11:46:36.410 Enigmail receives the event that the compose window is to be closed. Enigmail reacts to this event by resetting some variables - certainly nothing that would cause a delay of more than 1-2 milliseconds.

The next thing 90 seconds later is that Enigmail is called to handle a PGP/MIME message.

I'm sorry, Enigmail does not do anything in between.

Enigmail is not involved into message sending at all. As far as I can tell from the SMTP log, the 90 seconds delay comes from the SMTP server/service/network, and not from anything else.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Patrick Brunschwig - 2016-04-16

status: open --> wont-fix
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Jürgen Rathlev - 2016-04-24

Log from Sysinternal ProcMon:
...
13:43:44,7004184 thunderbird.exe 20284 WriteFile E:\Temp\tb-logs\smtp.log SUCCESS Offset: 3.649, Length: 73
...
13:43:44,8137470 thunderbird.exe 20284 TCP Send Buero:53264 -> Buero:53265 SUCCESS Length: 1, startime: 9206786, endtime: 9206786, seqnum: 0, connid: 0
13:44:09,9101033 thunderbird.exe 20284 CreateFile C:\Users...\Documents\Mail\cache2\entries SUCCESS Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
...
13:44:09,9103941 thunderbird.exe 20284 CloseFile C:\Users...\Documents\Mail\cache2\entries SUCCESS
13:44:09,9107893 thunderbird.exe 20284 CreateFile C:\Users...\Documents\Mail\cache2\entries SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
...
13:44:09,9112737 thunderbird.exe 20284 CloseFile C:\Users...\Documents\Mail\cache2\entries SUCCESS
13:44:09,9117451 thunderbird.exe 20284 CreateFile C:\Users...\Documents\Mail\cache2 SUCCESS Desired Access: Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Open For Free Space Query, Attributes: n/a, ShareMode: None, AllocationSize: n/a, OpenResult: Opened
...
13:44:09,9119547 thunderbird.exe 20284 CloseFile C:\Users...\Documents\Mail\cache2 SUCCESS
13:44:19,6590433 thunderbird.exe 20284 Thread Exit SUCCESS Thread ID: 20924, User Time: 0.0000000, Kernel Time: 0.0156250
...
13:44:19,9103371 thunderbird.exe 20284 CreateFile C:\Users...\Documents\Mail\cache2 SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
...
13:44:19,9126503 thunderbird.exe 20284 CloseFile C:\Users...\Documents\Mail\cache2 SUCCESS
13:44:38,4869368 thunderbird.exe 20284 TCP Receive Buero:53265 -> Buero:53264 SUCCESS Length: 1, seqnum: 0, connid: 0
13:44:38,4870088 thunderbird.exe 20284 TCP Send Buero:53264 -> Buero:53265 SUCCESS Length: 1, startime: 9212154, endtime: 9212154, seqnum: 0, connid: 0
...
13:44:38,4886441 thunderbird.exe 20284 TCP Receive Buero:53265 -> Buero:53264 SUCCESS Length: 1, seqnum: 0, connid: 0
13:44:38,4886793 thunderbird.exe 20284 TCP Send Buero:53264 -> Buero:53265 SUCCESS Length: 1, startime: 9212154, endtime: 9212154, seqnum: 0, connid: 0
13:45:13,8500072 thunderbird.exe 20284 CloseFile F:\Temp\nsemail-5.eml SUCCESS
13:45:13,8505106 thunderbird.exe 20284 WriteFile E:\Temp\tb-logs\smtp.log SUCCESS Offset: 4.646, Length: 72
...

log from Thunderbird SMTP:
...
2016-04-24 11:43:44.737000 UTC - 20280[2e11140]: SMTP entering state: 10
2016-04-24 11:45:13.846000 UTC - 20280[2e11140]: SMTP entering state: 12
...

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Thunderbird with Enigmail on Windows 10 freezes after sending mail

OpenPGP addon for Mozilla Thunderbird

Searches

Help

#595 Thunderbird with Enigmail on Windows 10 freezes after sending mail

Related

Discussion

Related