Windows上のEmacsで Wanderlust を使っていて長年悩まされていたのがSMTP error。送信時に SMTP error と出て送信が中断してしまいます。何度か繰り返すと成功するのですが、たまに失敗時にも送れてしまうことがあるらしく何通も相手に送ってしまっている場合があります。
長年の経験で原因はどうも SSL/TLS まわりにあるらしいことが分かっています。SSL/TLSを使わないと発生しないので。Emacs組み込みのgnutlsを使うか外部のコマンドを使うかでも挙動が変わってきます。SSL/TLSを使うと受信時にも時々エラーが発生して何度か繰り返すとうまく行くことがあります。
この問題が解決するならばとGnusへの移行を試してみたこともあるのですが同じ問題が発生したので無意味でした。
今日少しこの問題を調査してみたのですが、結論から言うと
(setq gnutls-log-level 5)
を設定したらSMTP errorが出なくなりました。
な、なんだってー！
このコードはgnutlsのログレベルを上げて沢山のログを出すようにしただけです。
gnutls-log-levelを2にして出たログが次です。
Sending...
gnutls.c: [1] (Emacs) connecting to host: ****.****.ne.jp
gnutls.c: [1] (Emacs) allocating credentials
gnutls.c: [2] (Emacs) allocating x509 credentials
gnutls.c: [2] (Emacs) using default verification flags
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=CORP\\srv-build-cd.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=****.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=****.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=CORP\\srv-build-cd.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: OU=Copyright (c) 1997 Microsoft Corp.,OU=Microsoft Corporation,CN=Microsoft Root Authority.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=****.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: C=US,ST=California,L=Newark,O=Logitech Inc,CN=Logitech Inc.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: C=US,O=MSFT,CN=Microsoft Authenticode(tm) Root Authority.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=CORP\\srv-build-cd.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=CORP\\srv-build-cd.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=****.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=Root Agency.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=dsalocal.intel.com.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=dsalocal.intel.com.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=dsalocal.intel.com.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=dsalocal.intel.com.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=dsalocal.intel.com.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=dsalocal.intel.com.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=dsalocal.intel.com.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=dsalocal.intel.com.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=dsalocal.intel.com.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=dsalocal.intel.com.
gnutls.c: [audit] There was a non-CA certificate in the trusted list: CN=dsalocal.intel.com.
gnutls.c: [1] (Emacs) setting the trustfile: c:/****/certs/ca-bundle.crt
gnutls.c: [1] (Emacs) gnutls callbacks
gnutls.c: [1] (Emacs) gnutls_init
gnutls.c: [1] (Emacs) got non-default priority string: NORMAL:%DUMBFW
gnutls.c: [1] (Emacs) setting the priority string
gnutls.c: [2] added 6 protocols, 29 ciphersuites, 18 sig algos and 9 groups into priority list
gnutls.c: [2] Keeping ciphersuite 13.02 (GNUTLS_AES_256_GCM_SHA384)
gnutls.c: [2] Keeping ciphersuite 13.03 (GNUTLS_CHACHA20_POLY1305_SHA256)
gnutls.c: [2] Keeping ciphersuite 13.01 (GNUTLS_AES_128_GCM_SHA256)
gnutls.c: [2] Keeping ciphersuite 13.04 (GNUTLS_AES_128_CCM_SHA256)
gnutls.c: [2] Keeping ciphersuite c0.2c (GNUTLS_ECDHE_ECDSA_AES_256_GCM_SHA384)
gnutls.c: [2] Keeping ciphersuite cc.a9 (GNUTLS_ECDHE_ECDSA_CHACHA20_POLY1305)
gnutls.c: [2] Keeping ciphersuite c0.ad (GNUTLS_ECDHE_ECDSA_AES_256_CCM)
gnutls.c: [2] Keeping ciphersuite c0.0a (GNUTLS_ECDHE_ECDSA_AES_256_CBC_SHA1)
gnutls.c: [2] Keeping ciphersuite c0.2b (GNUTLS_ECDHE_ECDSA_AES_128_GCM_SHA256)
gnutls.c: [2] Keeping ciphersuite c0.ac (GNUTLS_ECDHE_ECDSA_AES_128_CCM)
gnutls.c: [2] Keeping ciphersuite c0.09 (GNUTLS_ECDHE_ECDSA_AES_128_CBC_SHA1)
gnutls.c: [2] Keeping ciphersuite c0.30 (GNUTLS_ECDHE_RSA_AES_256_GCM_SHA384)
gnutls.c: [2] Keeping ciphersuite cc.a8 (GNUTLS_ECDHE_RSA_CHACHA20_POLY1305)
gnutls.c: [2] Keeping ciphersuite c0.14 (GNUTLS_ECDHE_RSA_AES_256_CBC_SHA1)
gnutls.c: [2] Keeping ciphersuite c0.2f (GNUTLS_ECDHE_RSA_AES_128_GCM_SHA256)
gnutls.c: [2] Keeping ciphersuite c0.13 (GNUTLS_ECDHE_RSA_AES_128_CBC_SHA1)
gnutls.c: [2] Keeping ciphersuite 00.9d (GNUTLS_RSA_AES_256_GCM_SHA384)
gnutls.c: [2] Keeping ciphersuite c0.9d (GNUTLS_RSA_AES_256_CCM)
gnutls.c: [2] Keeping ciphersuite 00.35 (GNUTLS_RSA_AES_256_CBC_SHA1)
gnutls.c: [2] Keeping ciphersuite 00.9c (GNUTLS_RSA_AES_128_GCM_SHA256)
gnutls.c: [2] Keeping ciphersuite c0.9c (GNUTLS_RSA_AES_128_CCM)
gnutls.c: [2] Keeping ciphersuite 00.2f (GNUTLS_RSA_AES_128_CBC_SHA1)
gnutls.c: [2] Keeping ciphersuite 00.9f (GNUTLS_DHE_RSA_AES_256_GCM_SHA384)
gnutls.c: [2] Keeping ciphersuite cc.aa (GNUTLS_DHE_RSA_CHACHA20_POLY1305)
gnutls.c: [2] Keeping ciphersuite c0.9f (GNUTLS_DHE_RSA_AES_256_CCM)
gnutls.c: [2] Keeping ciphersuite 00.39 (GNUTLS_DHE_RSA_AES_256_CBC_SHA1)
gnutls.c: [2] Keeping ciphersuite 00.9e (GNUTLS_DHE_RSA_AES_128_GCM_SHA256)
gnutls.c: [2] Keeping ciphersuite c0.9e (GNUTLS_DHE_RSA_AES_128_CCM)
gnutls.c: [2] Keeping ciphersuite 00.33 (GNUTLS_DHE_RSA_AES_128_CBC_SHA1)
gnutls.c: [2] Advertizing version 3.4
gnutls.c: [2] Advertizing version 3.3
gnutls.c: [2] Advertizing version 3.2
gnutls.c: [2] Advertizing version 3.1
gnutls.c: [2] HSK[0000000005c5d140]: sent server name: '****.****.ne.jp'
gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again. [73 times]
gnutls.c: [audit] FFDHE groups advertised, but server didn't support it; falling back to server's choice
gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again. [295 times]
gnutls.c: [2] (Emacs) Deallocating x509 credentials
Invalid response: ... Recipient ok
Invalid response: RCPT TO:<****@****.jp>
wl-draft-send-mail-with-smtp: SMTP error
SMTP error
「non-fatal error: Resource temporarily unavailable, try again.」というのが73回+295回も繰り返されているのが気になります。
このエラーメッセージはgnutlsのGNUTLS_E_AGAINに対応するもののようです。
GNUTLS_E_AGAINはあちこちで発生するようです。
もう少し詳細なログが出ないかgnutls-log-levelを5にして再度試してみたところ、何回繰り返してもエラーが発生しません。
ログを見ると次のように大量のretryメッセージが出ていました。
gnutls.c: [3] ASSERT: ../../../gnutls-3.6.10/lib/nettle/mpi.c[wrap_nettle_mpi_print]:60
gnutls.c: [4] HSK[00000000021cc030]: CLIENT KEY EXCHANGE was queued [262 bytes]
gnutls.c: [4] REC[00000000021cc030]: Sent ChangeCipherSpec
gnutls.c: [5] REC[00000000021cc030]: Initializing epoch #1
gnutls.c: [5] REC[00000000021cc030]: Epoch #1 ready
gnutls.c: [4] HSK[00000000021cc030]: Cipher Suite: GNUTLS_DHE_RSA_AES_256_GCM_SHA384
gnutls.c: [4] HSK[00000000021cc030]: Initializing internal [write] cipher sessions
gnutls.c: [4] HSK[00000000021cc030]: recording tls-unique CB (send)
gnutls.c: [4] HSK[00000000021cc030]: FINISHED was queued [16 bytes]
gnutls.c: [5] REC[00000000021cc030]: Preparing Packet Handshake(22) with length: 7 and min pad: 0
gnutls.c: [5] REC[00000000021cc030]: Sent Packet[2] Handshake(22) in epoch 0 and length: 12
gnutls.c: [5] REC[00000000021cc030]: Preparing Packet Handshake(22) with length: 262 and min pad: 0
gnutls.c: [5] REC[00000000021cc030]: Sent Packet[3] Handshake(22) in epoch 0 and length: 267
gnutls.c: [5] REC[00000000021cc030]: Preparing Packet ChangeCipherSpec(20) with length: 1 and min pad: 0
gnutls.c: [5] REC[00000000021cc030]: Sent Packet[4] ChangeCipherSpec(20) in epoch 0 and length: 6
gnutls.c: [5] REC[00000000021cc030]: Preparing Packet Handshake(22) with length: 16 and min pad: 0
gnutls.c: [5] REC[00000000021cc030]: Sent Packet[1] Handshake(22) in epoch 1 and length: 45
gnutls.c: [3] ASSERT: ../../gnutls-3.6.10/lib/buffers.c[get_last_packet]:1168
gnutls.c: [3] ASSERT: ../../gnutls-3.6.10/lib/buffers.c[_gnutls_io_read_buffered]:589
gnutls.c: [3] (Emacs) retry: Resource temporarily unavailable, try again.
gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again.
gnutls.c: [3] ASSERT: ../../gnutls-3.6.10/lib/buffers.c[get_last_packet]:1168
gnutls.c: [3] ASSERT: ../../gnutls-3.6.10/lib/buffers.c[_gnutls_io_read_buffered]:589
gnutls.c: [3] (Emacs) retry: Resource temporarily unavailable, try again.
gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again.
gnutls.c: [3] ASSERT: ../../gnutls-3.6.10/lib/buffers.c[get_last_packet]:1168
gnutls.c: [3] ASSERT: ../../gnutls-3.6.10/lib/buffers.c[_gnutls_io_read_buffered]:589
gnutls.c: [3] (Emacs) retry: Resource temporarily unavailable, try again.
gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again.
gnutls.c: [3] ASSERT: ../../gnutls-3.6.10/lib/buffers.c[get_last_packet]:1168
gnutls.c: [3] ASSERT: ../../gnutls-3.6.10/lib/buffers.c[_gnutls_io_read_buffered]:589
gnutls.c: [3] (Emacs) retry: Resource temporarily unavailable, try again.
gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again.
gnutls.c: [3] ASSERT: ../../gnutls-3.6.10/lib/buffers.c[get_last_packet]:1168
....繰り返し
これは推測なのですが、リトライ時のメッセージ出力量が増えたことによってリトライの間隔が延びたことが影響しているのではないでしょうか。これらのメッセージは逐一ミニバッファに出るので体感できるくらいには遅くなります。
(setq gnutls-log-level 5) を設定したまま1～2日ほど使ってみましたが今のところエラーは発生していません。
これ以上深くは追っていないのですが、またエラーが発生したら調べてみようと思います。
2020-06-21追記:未だにエラーが出ません。
