3.2.36.0: some notifications not sending mail

[knoebe 1]

I'm using the "Email Notifications" plugin for sending mails. Test notification and some other (new release, plugin installed/unistalled) notifications are working. Before the server update I used the "Video playback started/stopped" notifications and they worked. Now the mail isn't generated. 

I sniffed with wireshark and see that the mail sending process is started but doesn't end properly. Is this a known problem? Didn't find anything in this forum.

[mastrmind11 717]

what does the log say?

[knoebe 1]

what does the log say?

 

This is the last (changed mail address):

2017-12-06 15:00:43.136 Info App: Emailing my@address.com with subject Emby: MediaCenter is playing Bite on PC1/media using MB-Classic

 

No error after this but it isn't sent.

[Luke 37259]

Check the spam folder of your email and make sure it didn't get caught in there.

 

Are you sending it to a Gmail address?

[knoebe 1]

It's not in the spam folder because it isn't sent properly to the mail server. The mail server is my own and as I wrote other notifications are sent.

[Luke 37259]

So the email event is in the log but you just never receive it?

[knoebe 1]

Yes it's logged normally like the working notifications. I updated to 3.2.50.0 today but it's the same problem. Additionally I tried another mail server but this played/stopped mails aren't sent. I see something like a timeout in the network traffic (wireshark).

[Luke 37259]

Ok, I'm not entirely sure what the issue is. Some network tracing might be needed to find out.

 

While we are here I would just like to point out that the email plugin is a community addition, and contributions are welcome. The source code can be found here:

 

https://github.com/MediaBrowser/email-notifications

 

Thanks !

[knoebe 1]

I don't think it's the plugin because other notification mails are sent.

 

This is from wireshark for the working notification:
No.     Time           Source                Destination           Protocol Length Info
      1 0.000000       192.168.1.80          192.168.1.50         TCP      66     60967 → 25 [sYN] Seq=0 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1
      2 0.002426       192.168.1.50         192.168.1.80          TCP      66     25 → 60967 [sYN, ACK] Seq=0 Ack=1 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1
      3 0.002525       192.168.1.80          192.168.1.50         TCP      54     60967 → 25 [ACK] Seq=1 Ack=1 Win=65536 Len=0
      4 0.004476       192.168.1.50         192.168.1.80          SMTP     144    S: 220 mail.mydomain.com Microsoft ESMTP MAIL Service ready at Wed, 6 Dec 2017 18:24:53 +0100
      5 0.004587       192.168.1.80          192.168.1.50         SMTP     66     C: EHLO wsMC1
      6 0.005506       192.168.1.50         192.168.1.80          SMTP     224    S: 250 mail.mydomain.com Hello [192.168.1.254] | 250 SIZE 36700160 | 250 PIPELINING | 250 DSN | 250 ENHANCEDSTATUSCODES | 250 STARTTLS | 250 8BITMIME | 250 BINARYMIME | 250 CHUNKING
      7 0.005599       192.168.1.80          192.168.1.50         SMTP     88     C: MAIL FROM:<emby@mydomain.com>
      8 0.018709       192.168.1.50         192.168.1.80          SMTP     75     S: 250 2.1.0 Sender OK
      9 0.018993       192.168.1.80          192.168.1.50         SMTP     86     C: RCPT TO:<emby@mydomain.com>
     10 0.019640       192.168.1.50         192.168.1.80          SMTP     78     S: 250 2.1.5 Recipient OK
     11 0.019777       192.168.1.80          192.168.1.50         SMTP     60     C: DATA
     12 0.020369       192.168.1.50         192.168.1.80          SMTP     100    S: 354 Start mail input; end with <CRLF>.<CRLF>
     13 0.021392       192.168.1.80          192.168.1.50         SMTP     291    C: DATA fragment, 237 bytes
     14 0.073553       192.168.1.50         192.168.1.80          TCP      60     25 → 60967 [ACK] Seq=352 Ack=322 Win=131072 Len=0
     15 0.073606       192.168.1.80          192.168.1.50         IMF      105    from: emby@mydomain.com, subject: Emby: Emby: Test Notification,  (text/plain)
     16 0.118715       192.168.1.50         192.168.1.80          TCP      60     25 → 60967 [ACK] Seq=352 Ack=373 Win=130816 Len=0
     17 0.181330       192.168.1.50         192.168.1.80          SMTP     195    S: 250 2.6.0 <15fd582dccc447b480a866e8d8e6f8de@mail.mydomain.com> [internalId=70819715743758, Hostname=mail.mydomain.com] Queued mail for delivery
     18 0.181546       192.168.1.80          192.168.1.50         TCP      54     60967 → 25 [FIN, ACK] Seq=373 Ack=493 Win=65024 Len=0
     19 0.182363       192.168.1.50         192.168.1.80          TCP      60     25 → 60967 [ACK] Seq=493 Ack=374 Win=130816 Len=0
     20 0.182621       192.168.1.50         192.168.1.80          TCP      60     25 → 60967 [FIN, ACK] Seq=493 Ack=374 Win=130816 Len=0
     21 0.182641       192.168.1.80          192.168.1.50         TCP      54     60967 → 25 [ACK] Seq=374 Ack=494 Win=65024 Len=0

 

The SMTP Log for this mail:
*,,Proxying inbound session with session id 08D52FFC29A5BA37
>,RSET,
<,250 2.0.0 Resetting,
>,XPROXYFROM SID=08D52FFC29A5BA37 IP=192.168.1.80 PORT=62111 DOMAIN=wsMC1 SEQNUM=1 PERMS=1789 AUTHSRC=Organization,
<,250 XProxyFrom accepted,
*,,sending message with RecordId 0 and InternetMessageId <c8c130d57cfa47fd84817d05c25722d0@mail.mydomain.com>
>,MAIL FROM:<emby@mydomain.com> SIZE=0,
>,RCPT TO:<emby@mydomain.com>,
<,250 2.1.0 Sender OK,
<,250 2.1.5 Recipient OK,
>,DATA,
<,354 Start mail input; end with <CRLF>.<CRLF>,
<,"250 2.6.0 <c8c130d57cfa47fd84817d05c25722d0@mail.mydomain.com> [internalId=70824010711044, Hostname=mail.mydomain.com] Queued mail for delivery",
*,,successfully added connection to cache. Current cache size is 1 
 
 
This is from wireshark for a "played" notification: 
No.     Time           Source                Destination           Protocol Length Info
      1 0.000000       192.168.1.80          192.168.1.50         TCP      66     61174 → 25 [sYN] Seq=0 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1
      2 0.000993       192.168.1.50         192.168.1.80          TCP      66     25 → 61174 [sYN, ACK] Seq=0 Ack=1 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1
      3 0.001067       192.168.1.80          192.168.1.50         TCP      54     61174 → 25 [ACK] Seq=1 Ack=1 Win=65536 Len=0
      4 0.002815       192.168.1.50         192.168.1.80          SMTP     144    S: 220 mail.mydomain.com Microsoft ESMTP MAIL Service ready at Wed, 6 Dec 2017 18:32:10 +0100
      5 0.002929       192.168.1.80          192.168.1.50         SMTP     66     C: EHLO wsMC1
      6 0.003879       192.168.1.50         192.168.1.80          SMTP     224    S: 250 mail.mydomain.com Hello [192.168.1.254] | 250 SIZE 36700160 | 250 PIPELINING | 250 DSN | 250 ENHANCEDSTATUSCODES | 250 STARTTLS | 250 8BITMIME | 250 BINARYMIME | 250 CHUNKING
      7 0.003973       192.168.1.80          192.168.1.50         SMTP     88     C: MAIL FROM:<emby@mydomain.com>
      8 0.011859       192.168.1.50         192.168.1.80          SMTP     75     S: 250 2.1.0 Sender OK
      9 0.011939       192.168.1.80          192.168.1.50         SMTP     86     C: RCPT TO:<emby@mydomain.com>
     10 0.013753       192.168.1.50         192.168.1.80          SMTP     78     S: 250 2.1.5 Recipient OK
     11 0.013821       192.168.1.80          192.168.1.50         SMTP     60     C: DATA
     12 0.014672       192.168.1.50         192.168.1.80          SMTP     100    S: 354 Start mail input; end with <CRLF>.<CRLF>
     13 0.014813       192.168.1.80          192.168.1.50         SMTP     292    C: DATA fragment, 238 bytes
     14 0.065248       192.168.1.50         192.168.1.80          TCP      60     25 → 61174 [ACK] Seq=352 Ack=323 Win=131072 Len=0
     15 100.957823     192.168.1.80          192.168.1.50         TCP      54     61174 → 25 [RST, ACK] Seq=323 Ack=352 Win=0 Len=0

 

The SMTP Log for this mail: 
*,,Proxying inbound session with session id 08D52FFC29A5BA3A
>,RSET,
<,250 2.0.0 Resetting,
>,XPROXYFROM SID=08D52FFC29A5BA3A IP=192.168.1.80 PORT=62136 DOMAIN=wsMC1 SEQNUM=1 PERMS=1789 AUTHSRC=Organization,
<,250 XProxyFrom accepted,
*,,sending message with RecordId 0 and InternetMessageId <030aa8ab41ec472abd8c451ee0c3ef19@mail.mydomain.com>
>,MAIL FROM:<emby@mydomain.com> SIZE=0,
>,RCPT TO:<emby@mydomain.com>,
<,250 2.1.0 Sender OK,
<,250 2.1.5 Recipient OK,
>,DATA,
<,354 Start mail input; end with <CRLF>.<CRLF>,
*,,Proxy layer started discarding data. Acking message as failed.

 

I'm not sure if the mail is ending properly with crlf.crlf

[knoebe 1]

Some news? Or is this working for other users?

[Luke 37259]

If it's in the log that the plugin is trying to send an email but you're not getting it, then I don't have an answer for you, sorry.

[knoebe 1]

To be sure: Are you saying the start/stop playing notifications are working for you? 

[mastrmind11 717]

To be sure: Are you saying the start/stop playing notifications are working for you? 

FWIW, the Pushover plugin is working for start/stop.  Dunno if it uses the same Emby notification pipeline or not, but maybe give that a try and see if it works for you?

[Luke 37259]

To be sure: Are you saying the start/stop playing notifications are working for you? 

 

The plugin is a community addition and I just don't have available bandwidth to test it personally, sorry.

[knoebe 1]

The plugin is a community addition and I just don't have available bandwidth to test it personally, sorry.

 

That's something I don't understand. While this was working with server version 3.2.34 and the same plugin and other notificications are working with this plugin but not start/stop - then it's the plugin and not the server. Ok.

[Luke 37259]

Because you can see the point in the server log where the server is passing the instruction to the plugin. 

 

I am happy to add a logging statement to the email plugin so that we can verify that the plugin thinks it has successfully sent an email based on the response it gets from the Microsoft .NET email api's.

[knoebe 1]

I am happy to add a logging statement to the email plugin so that we can verify that the plugin thinks it has successfully sent an email based on the response it gets from the Microsoft .NET email api's.

 

Thanks, I saw you added this now. The test notifications has now the "completed" log entry:

2017-12-10 19:26:35.881 Info App: Sending email emby@mydomain.com with subject Emby: Emby: Test Notification

2017-12-10 19:26:36.074 Info App: Completed sending email emby@mydomain.com with subject Emby: Emby: Test Notification

 

But the start/stop notification doesn't complete:

2017-12-10 19:28:14.611 Info App: Sending email emby@mydomain.com with subject Emby: MediaCenter has finished playing Eine schrecklich nette Familie - S7, Ep6 - Buds verzweifelte Suche on Edge using Emby Mobile

 

Maybe the timeout is to low?

Edited December 10, 2017 by knoebe

[Luke 37259]

Looking at the code of the plugin the timeout is 20 seconds. That seems like it should be enough.

[knoebe 1]

Found the bug after testing with your plugin code: The mail fails because the mail body is empty for this mails. Can you add a check for this and fill the empty body with the subject or some other text?

[Luke 37259]

Why do you believe this to be the case?

[knoebe 1]

First I tried await client.SendMailAsync(mail).ConfigureAwait(false); with strings for rcpt, to, subject and body instead of "mail". Worked. Then I tried with options.EmailTo, mail.Subject and the others one after each and on mail.body no mail was sent.

 

After this I changed Body = request.Description to an empty string: no mail. With a string for body the mail was sent.

[Luke 37259]

Are you sure it is consistent? because it is possible this is happening at random and therefore is coincidental.

 

The MSDN documentation does not mention the Body being required so this sounds like a requirement of whatever server is receiving the email.

[knoebe 1]

I don't know what else I could test. Empty body = no mail, filled body = mail. With a space the mail is sent too, just not with an empty body. If you look at the mail log in the first posts I thought the mail wasn't finished correctly. I think this is the case because of the empty body it can't close the submission. Didn't find if required or not but it doesn't send mail for my Exchange server and my providers mail server.

[Luke 37259]

Ok, it's fine. I don't think it's a problem to always include a body.

[knoebe 1]

Thanks! With this change future notifications without body doesn't fail too