search

letscontrolit / ESPEasy

Easy MultiSensor device based on ESP8266/ESP32
http://www.espeasy.com
Other
3.26k stars 2.21k forks source link

[BUG] Notification - EMail results in a timeout #5121

Open kuppe234 opened 2 weeks ago

kuppe234 commented 2 weeks ago

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 commented 2 weeks ago

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 commented 2 weeks ago

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

TD-er commented 2 weeks ago

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

TD-er commented 2 weeks ago

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

TD-er commented 2 weeks ago

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

TD-er commented 2 weeks ago

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

kuppe234 commented 2 weeks ago

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 commented 2 weeks ago

Please set log level to debug and provide us new log

TD-er commented 2 weeks ago

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 commented 2 weeks ago

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 commented 1 week ago

Sorry, please wait until tomorrow.

TD-er commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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

kuppe234 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

@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 commented 1 week ago

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 commented 1 week ago

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

Indeed, it is a blocking code monster.

kuppe234 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

@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: https://github.com/letscontrolit/ESPEasy/blob/762b94abbe83d3e67dd5659cae4d285be562f0b1/src/_N001_Email.cpp#L442 https://github.com/letscontrolit/ESPEasy/blob/762b94abbe83d3e67dd5659cae4d285be562f0b1/src/_N001_Email.cpp#L460 https://github.com/letscontrolit/ESPEasy/blob/762b94abbe83d3e67dd5659cae4d285be562f0b1/src/_N001_Email.cpp#L476

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 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

Great!

uzi18 commented 1 week ago

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

kuppe234 commented 1 week ago

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 commented 3 days ago

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 commented 2 days ago

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 commented 2 days ago

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 commented 2 days ago

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.