[BUG] Notification - EMail results in a timeout

[kuppe234]

Hello,
I am using the feature of E-Mail-Notifikation.
On newer Firmware (August 2024 and follow) I cant use this feature anymore.
I'm using the same configuration like on my old Firmware from october 2023, but I'm get a timeout:

144457851: Email: Initializing ...
144449784: Email: Max Allowed Timeout is 8 secs
144457851: Timeout while reading input data! str: ``
144457858: Email: Connection Closed With Error. Used header: From: giesomat-1 ^^To: dhe@gerbil.schenkenberg.net^^Subject: Test^^Reply

On Serverside I can see a connect, follow by a disconnect 8 seconds later.
Have anyone an idea, whats wrong?
Note: I had test this with different smtp-servers and different accounts. The smtp-servers can receive mails on port 25.

Greetings, kuppe.

[TD-er]

There has been a change in the email notification plugin, to support larger timeouts.
Maybe your settings need to be updated?
Can you try saving the email settings again by opening the page and submit the settings?

[kuppe234]

Doesn't help. I had testet various timeouts. For the tests, I deleted all settings and made new ones, but without success.

[TD-er]

Do you run this on ESP32 or ESP8266?
Which exact filename (see sysinfo page) do you use?

[TD-er]

Do you send to a single receiver or multiple? (just looking through the most recent commits to that file)

[TD-er]

Can you also test using the test button on the config page?

[TD-er]

Can you also set the timeout to 12 or 20 seconds?

[kuppe234]

• I run this on ESP32
• Build:⋄ 20240912 - Mega32
  System Libraries:⋄ ESP32 SDK 4.4.6
  Git Build:⋄ mega_73d6ff7
  Plugin Count:⋄ 48 ["Normal"]
  Build Origin: Self built
  Build Time:⋄ Sep 12 2024 18:47:40
  Binary Filename:⋄ ESP_Easy_mega_20240912_normal_ESP32_4M316k
  Build Platform:⋄ Linux-6.10.6-200.fc40.x86_64-x86_64-with-glibc2.39
  Git HEAD:⋄ mega_73d6ff7
• I have tested various SMTP servers. The connection is established, but no data is sent. The ESP shows the timeout in the log, the mail server terminates the connection with the message “Timeout”.
• I have always carried out the tests with the test button. The service is also enabled.
• 12 or 20 seconds or another timeout do not change anything.

I think there is a timeout when generating the mail content on the ESP32. An empty mail is then not sent and the connection is terminated.

[uzi18]

Please set log level to debug and provide us new log

[TD-er]

OK, found a few issues in the email code, though not sure it is "the fix"
Maybe the parsing for replies is now using a buffer length which is too short.
Effectively those are now 256 bytes where they were 1024 before.

I will make a test build.

[TD-er]

Made a test build with both bin files (factory and OTA bin) for you:
ESP_Easy_mega_20240914_normal_ESP32_4M316k.factory.zip

Please test on an easily assessible node as I was working on a test branch, with lots of other changes in the platform code....

[kuppe234]

Sorry, please wait until tomorrow.

[TD-er]

Maybe you can then test this build: https://github.com/letscontrolit/ESPEasy/actions/runs/10874920584
I did set the timeout in the client connection itself.

[kuppe234]

I'm sorry, but it doesn't work.
I used the version https://github.com/letscontrolit/ESPEasy/actions/runs/10874920584 because I need ETH support.

Here are some useful (I hope) logs (Loglevel 4):
ESP_Easy_mega_20231016_normal_ESP32_4M316k_ETH Oct 16 2023 (working)

7817161: EMAIL: Connecting to mail.my-domain.de25
7817222: 220 mail.my-domain.de ESMTP Exim 4.94.2 Mon, 16 Sep 2024 13:28:22 +0200^
7817223: EHLO hrz.my-domain.de
7817312: 250-mail.my-domain.de Hello wesp-a13-069-0-2.mmt.my-domain.de [172.28.4.32]^
7817313: 250-SIZE 209715200^
7817313: 250-8BITMIME^
7817314: 250-VRFY^
7817314: 250-PIPELINING^
7817314: 250-PIPE_CONNECT^
7817315: 250-CHUNKING^
7817315: 250-STARTTLS^
7817316: 250-SMTPUTF8^
7817316: 250 HELP^
7817316: MAIL FROM:
7817364: 250 OK^
7817366: Email: To dhe@hrz.my-domain.de
7817366: RCPT TO:
7817417: 250 Accepted^
7817417: DATA
7817465: 354 Enter message, ending with '.' on a line by itself^
7817465: From: A13.Proto2 ^^To: dhe@hrz.my-domain.de^^Subject: A13.Proto2: Schrankoeffnung^^Reply-To: A13.Prot
7817481: 250 OK id=1sq9u2-00FXhj-KG^
7817484: EMAIL: Connection Closed Successfully

ESP_Easy_mega_20240915_normal_ESP32_4M316k_ETH Sep 15 2024 (from website above, not working)

6410865: Email: Connecting to mail.my-domain.de:25
6410886: Email: Initializing ...
6410886: Email: Max Allowed Timeout is 8 secs
6418889: Timeout while reading input data! str: ``

I use 2 identical ESP32 with Ethernet connection and the same configuration.

[TD-er]

It looks like the 2nd logs do not have the debug log level set, is that correct?

[kuppe234]

The debug level is the same for both: "Debug More (4)".

Here is a more detailed log of the current firmware with the e-mail timeout (complete, no line deleted):

39063: ESP32: Raw temperature value: 132
40063: ESP32: Raw temperature value: 131
41063: ESP32: Raw temperature value: 131
42065: ESP32: Raw temperature value: 132
43063: ESP32: Raw temperature value: 131
44063: ESP32: Raw temperature value: 132
45065: ESP32: Raw temperature value: 132
46063: ESP32: Raw temperature value: 132
47063: ESP32: Raw temperature value: 132
48065: ESP32: Raw temperature value: 132
48244: UDP  : 172.28.4.32 (1) 24:6F:28:93:6E:18,172.28.4.32,1
48246: EVENT: p2pNode#Connected=1,'A13.Proto2','20231016'
48258: EVENT: p2pNode#Connected=1,'A13.Proto2','20231016' Processing: 12 ms
48261: UDP  : 172.28.4.32 (1) 24:6F:28:93:6E:18,172.28.4.32,1
48828: SaveToFile: NotificationSettings file: notification.dat task: 1
48829: SaveToFile: free stack: 6832
48898: FILE : Saved notification.dat offset: 0 size: 1000
48898: SaveToFile: free stack after: 6832
48924: ESPEasy console using ESPEasySerial
48925: Skip saving settings, not changed
48936: Skip saving SecuritySettings, not changed
49023: static_file: /favicon.ico to: 134.109.142.69
49048: HTML : Request file /favicon.ico
49067: ESP32: Raw temperature value: 132
49090: Email: Connecting to mail.my-domain.de:25
49109: Email: Initializing ...
49109: Email: Max Allowed Timeout is 8 secs
57112: Timeout while reading input data! str: ``
57113: Email: Initialization Fail
57125: Email: Connection Closed With Error. Used header: From: A13.Proto1 ^^To: dhe@hrz.my-domain.de^^Subjec
57171: ESP32: Raw temperature value: 132
58191: ESP32: Raw temperature value: 132

It is strange that between millisecond 49109 and 57112 no other line appears in the log as before or after. The ESP seems to stand still for 8 seconds, as if the email task is blocking everything.

[TD-er]

It is strange that between millisecond 49109 and 57112 no other line appears in the log as before or after. The ESP seems to stand still for 8 seconds, as if the email task is blocking everything.

Looking at the code, that doesn't seems so 'strange'...

[thomastech]

Drat. I'm the guy that updated the SMTP code to work with a new mail server at my ISP. I was expecting the changes to be backwards compatible. But unfortunately I couldn't validate this since I don't use a mail server that works with the old version.

But I can test any fixes you apply, to confirm they are compatible with both SMTP mail server handshakes.

[TD-er]

@thomastech Not sure if you caused these issues or maybe triggered some really flaky and bad code which was the old email implementation.

I've been looking at the code this morning and at some point I had to stop while I have still some nails and hair left.

Let's say there are more elegant ways to do stuff.

I will commit a few of my changes, to see if it still builds and/or maybe even does change some behavior.
However I think this code really needs some TLC... ehh refactoring... ehh redesign.

[TD-er]

Build running here: https://github.com/letscontrolit/ESPEasy/actions/runs/10912239870

Let's see if I have some time tomorrow to look into this and do some cleanup of the code.

[thomastech]

However I think this code really needs some TLC... ehh refactoring... ehh redesign.

Indeed, it is a blocking code monster.

[kuppe234]

I have tested previous versions of _N001_Email.cpp:

before 2024-04-06: works
before 2024-08-01: no longer works (error as described in the issue)
2024-08-01 until now: does not work (error as described in the issue)

The solution with the version before 2024-04-06 works for me. I can live with this backport.

[TD-er]

The solution with the version before 2024-04-06 works for me. I can live with this backport.

For me it isn't acceptable it ain't working anymore, so we will have to fix it anyway.

[uzi18]

@TD-er @thomastech @tonhuisman First problem is when server is really fast, so when you flush data from server you can't find status code 220
BTW flush was not there before, so it was introduced when added support for slower servers.

Another bug/problem are here:

ESPEasy/src/_N001_Email.cpp

Line 442 in 762b94a

bool NPlugin_001_MTA(WiFiClient& client, const String& aStr, uint16_t aWaitForPattern, uint16_t timeout)

ESPEasy/src/_N001_Email.cpp

Line 460 in 762b94a

const String aWaitForPattern_str = strformat(F("%d "), aWaitForPattern);

ESPEasy/src/_N001_Email.cpp

Line 476 in 762b94a

line.replace("-", " "); // Must Remove optional dash from MTA response code.

We wait for status code from server but you can find response could be "220 domain", "220-domain" or even"220+domain".
Created PR for your repo so take a look - both bugs should be addressed.

[TD-er]

I just merged @uzi18 's PR and the build is running here: https://github.com/letscontrolit/ESPEasy/actions/runs/10954520659

N.B. there is another known issue when having rules enabled, which I'm working on.
So please disable rules when running this test build.

[thomastech]

Installed test build and my fussy email notification is still working. Here is the log (with sensitive info obscured):

205737: Email: Connecting to mail.smtp2go.com:2525
205860: Email: Initializing ...
205860: Email: Max Allowed Timeout is 10 secs
205867: static_file: /favicon.ico to: 192.168.1.156
205883: HTML : Request file /favicon.ico
206662: 220 mail.smtp2go.com ESMTP Exim 4.97.1-S2G Fri, 20 Sep 2024 15:19:25 +0000^
206662: Email: Sending EHLO domain
206662: EHLO smtp2go.com
207675: 250-mail.smtp2go.com Hello smtp2go.com [71.197.127.97]^
207676: Email: Packet Rcvd is: > 250-SIZE 52428800^ <
207676: Email: Sending User/Pass
207676: AUTH LOGIN
208611: 334 xxxxxxxWU6^
208612: xxxxxxxnb19pb3Q=
209230: 334 xxxxxxxvcmQ6^
209230: XXXXXXXalpURjJkMmt3
209631: 235 Authentication succeeded^
209631: Email: Credentials Accepted
209631: Email: Sending email Addr
209631: MAIL FROM:
210422: 250 sender ok.^
210422: Email: Receiver(s): user@email.com
210422: Email: To anyone@email.com
210422: RCPT TO:
210856: 250 Accepted ^
210856: DATA
211491: 354 Enter message, ending with '.' on a line by itself^
211491: From: MILK-MATE ^^To: anyone@email.com^^Subject: MILK-MATE has rebooted!^^Reply-To: MILK-MATE 
211847: 250 OK id=1srfPu-FnQW0hPnPam-Iirh^
211847: QUIT
211902: 500 unrecognized command^
211904: Email: Connection Closed Successfully

[TD-er]

Great!

[uzi18]

@kuppe234 please confirm @TD-er build is working for you.

[kuppe234]

The test setup "ESP_Easy_mega_20240920_normal_ESP32_4M316k_ETH.bin" works in my environment. There are no blockages or timeouts.

7840: Email: Connecting to mail.my-domain.de:25
7857: Email: Initializing ...
7858: Email: Max Allowed Timeout is 8 secs
7862: 220 mail.my-domain.de ESMTP Exim 4.94.2 Sat, 21 Sep 2024 11:39:11 +0200^
7862: Email: Sending EHLO domain
7862: EHLO hrz.my-domain.de
7911: 250-mail.my-domain.de Hello wesp-a13-069-0-2.mmt.my-domain.de [172.28.4.32]^
7912: Email: Packet Rcvd is: > 250-SIZE 209715200^ <
7912: Email: Sending User/Pass
7912: Email: Sending email Addr
7912: MAIL FROM:
7957: 250 OK^
7957: Email: Receiver(s): dhe@hrz.my-domain.de
7958: Email: To dhe@hrz.my-domain.de
7958: RCPT TO:
8012: 250 Accepted^
8012: DATA
8058: 354 Enter message, ending with '.' on a line by itself^
8058: From: A13.Proto2 ^^To: dhe@hrz.my-domain.de^^Subject: A13.Proto2: Schrankoeffnung^^Reply-To: A13.Prot
8073: 250 OK id=1srwa7-009ktT-G8^
8074: QUIT
8122: 221 mail.my-domain.de closing connection^
8125: Email: Connection Closed Successfully

Unfortunately, I can't test more now because I'm on the road.
Thank you for the effort to localize the error.

[TD-er]

Should be merged in the 'mega' branch and also made available here: https://td-er.nl/ESPEasy/latest/

N.B. please test this 'latest' only on nodes which are easily reachable when things go wrong.
the build is based on the latest ESP-IDF5.3.1 code (for LittleFS builds)
It has the rules upload bug fixed and not being able to save taskname (and some other parameters) while rules are active.

[thomastech]

N.B. please test this 'latest' only on nodes which are easily reachable when things go wrong.

Have installed test release. No issues during installation, appears to be working. Will run overnight and report back if I discover any problems.

[TD-er]

The reason I asked was because I had on 1 board the issue where the file system could not be mounted and thus ESPEasy did a factory reset.

I have not seen this happening again, so it might still have been something I did wrong, but better safe than sorry.

[kuppe234]

I have built a new firmware with the current sources. E-mail now works perfectly. I have a few rules running for the mail. No problems.
The update of a configured ESP also worked without any problems, all files and configurations have been retained.
I use the variant ESP_Easy_mega_20240926_normal_ESP32_4M316k_ETH.