Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[v3] no mails are being sent #4760

Closed
himpierre opened this issue Feb 5, 2023 · 48 comments · Fixed by #4904
Closed

[v3] no mails are being sent #4760

himpierre opened this issue Feb 5, 2023 · 48 comments · Fixed by #4904
Labels

Comments

@himpierre
Copy link

Describe the bug
I have set the SMTP variables in .env and I can see, greenlight is trying to sent mail but it never makes a connect to my configured mail server. Here is what I see in the logs.

I, [2023-02-05T15:15:19.920286 #123]  INFO -- : [5b477e5a-a822-4158-94de-1870fbb65452]   Parameters: {"user"=>{"language"=>"en", "invite_token"=>"[FILTERED]", "name"=>"name name", "email"=>"emailadress", "password"=>"[FILTERED]", "password_confirmation"=>"[FILTERED]"}, "token"=>"[FILTERED]"}
I, [2023-02-05T15:15:20.170819 #123]  INFO -- : [5b477e5a-a822-4158-94de-1870fbb65452] [ActiveJob] Enqueued ActionMailer::MailDeliveryJob (Job ID: 77878615-3a7c-4c80-a95f-25d88679a95e) to Async(greenlight_v3_production_mailing) with arguments: "UserMailer", "activate_account_email", "deliver_now", {:params=>{:user=>#<GlobalID:0x00007f835a363708 @uri=#<URI::GID gid://greenlight/User/cc7a1f45-60a8-44d3-92e4-cddc3da469e2>>, :expires_in=>Sun, 05 Feb 2023 16:15:20.170027907 UTC +00:00, :activation_url=>"https://letsmeet.domain/activate_account/NishI0TEA0tHhoGcrCJrpEZUQixN1Gc4JnmPwDWr", :base_url=>"https://letsmeet.domain", :provider=>"greenlight"}, :args=>[]}
I, [2023-02-05T15:15:20.173809 #123]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [77878615-3a7c-4c80-a95f-25d88679a95e] Performing ActionMailer::MailDeliveryJob (Job ID: 77878615-3a7c-4c80-a95f-25d88679a95e) from Async(greenlight_v3_production_mailing) enqueued at 2023-02-05T15:15:20Z with arguments: "UserMailer", "activate_account_email", "deliver_now", {:params=>{:user=>#<GlobalID:0x00007f8359a5dc30 @uri=#<URI::GID gid://greenlight/User/cc7a1f45-60a8-44d3-92e4-cddc3da469e2>>, :expires_in=>Sun, 05 Feb 2023 16:15:20.170027907 UTC +00:00, :activation_url=>"https://letsmeet.domain/activate_account/NishI0TEA0tHhoGcrCJrpEZUQixN1Gc4JnmPwDWr", :base_url=>"https://letsmeet.domain", :provider=>"greenlight"}, :args=>[]}

To Reproduce
Steps to reproduce the behavior:

  1. Try to register
  2. Wait for mail
  3. Nothing happens

Expected behavior
Mails are recieved.

Actual behavior
No mails.

Greenligght: 3.0 beta 15
BigBlueButton: 2.6.0-rc2

@himpierre himpierre added the bug label Feb 5, 2023
@farhatahmad
Copy link
Collaborator

Is there any more logs after that? This is the action preparing to perform and then performing. There should be a bit more logs on whether it succeeded or failed

@himpierre
Copy link
Author

himpierre commented Feb 6, 2023

Yes. Here the complete log. (anonymized)

I, [2023-02-06T15:34:40.751245 #123]  INFO -- : [9e84b895-dfc6-4f3d-b8ed-352843545a80]   Parameters: {"user"=>{"language"=>"en", "invite_token"=>"[FILTERED]", "name"=>"my name", "email"=>"me@email.domain", "password"=>"[FILTERED]", "password_confirmation"=>"[FILTERED]"}, "token"=>"[FILTERED]"}
I, [2023-02-06T15:34:41.003287 #123]  INFO -- : [9e84b895-dfc6-4f3d-b8ed-352843545a80] [ActiveJob] Enqueued ActionMailer::MailDeliveryJob (Job ID: 04d185a4-02d8-4823-b0e4-faf475e084ea) to Async(greenlight_v3_production_mailing) with arguments: "UserMailer", "activate_account_email", "deliver_now", {:params=>{:user=>#<GlobalID:0x00007f83561a15b8 @uri=#<URI::GID gid://greenlight/User/5fc6f7fa-3361-4fcd-a6a7-730bd3d79d11>>, :expires_in=>Mon, 06 Feb 2023 16:34:41.001775871 UTC +00:00, :activation_url=>"https://letsmeet.my.domain/activate_account/AmIpGpKCVYCR7FZX2lsSswkVRHPBsUqoR3wpoUyv", :base_url=>"https://letsmeet.my.domain", :provider=>"greenlight"}, :args=>[]}
I, [2023-02-06T15:34:41.007348 #123]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [04d185a4-02d8-4823-b0e4-faf475e084ea] Performing ActionMailer::MailDeliveryJob (Job ID: 04d185a4-02d8-4823-b0e4-faf475e084ea) from Async(greenlight_v3_production_mailing) enqueued at 2023-02-06T15:34:41Z with arguments: "UserMailer", "activate_account_email", "deliver_now", {:params=>{:user=>#<GlobalID:0x00007f83561a9bc8 @uri=#<URI::GID gid://greenlight/User/5fc6f7fa-3361-4fcd-a6a7-730bd3d79d11>>, :expires_in=>Mon, 06 Feb 2023 16:34:41.001775871 UTC +00:00, :activation_url=>"https://letsmeet.my.domain/activate_account/AmIpGpKCVYCR7FZX2lsSswkVRHPBsUqoR3wpoUyv", :base_url=>"https://letsmeet.my.domain", :provider=>"greenlight"}, :args=>[]}
I, [2023-02-06T15:34:41.013704 #123]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [04d185a4-02d8-4823-b0e4-faf475e084ea]   Rendered user_mailer/activate_account_email.html.erb within layouts/mailer (Duration: 0.5ms | Allocations: 226)
I, [2023-02-06T15:34:41.013956 #123]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [04d185a4-02d8-4823-b0e4-faf475e084ea]   Rendered layout layouts/mailer.html.erb (Duration: 0.8ms | Allocations: 305)
I, [2023-02-06T15:34:41.014852 #123]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [04d185a4-02d8-4823-b0e4-faf475e084ea]   Rendered user_mailer/activate_account_email.text.erb within layouts/mailer (Duration: 0.5ms | Allocations: 192)
I, [2023-02-06T15:34:41.014936 #123]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [04d185a4-02d8-4823-b0e4-faf475e084ea]   Rendered layout layouts/mailer.text.erb (Duration: 0.7ms | Allocations: 234)
I, [2023-02-06T15:34:41.015959 #123]  INFO -- : [9e84b895-dfc6-4f3d-b8ed-352843545a80] [active_model_serializers] Rendered CurrentUserSerializer with ActiveModelSerializers::Adapter::Json (5.09ms)
I, [2023-02-06T15:34:41.022447 #123]  INFO -- : [9e84b895-dfc6-4f3d-b8ed-352843545a80] Completed 201 Created in 271ms (Views: 8.5ms | ActiveRecord: 24.4ms | Allocations: 11322)
I, [2023-02-06T15:34:41.022167 #123]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [04d185a4-02d8-4823-b0e4-faf475e084ea] Delivered mail 63e11e1148e1_7ba30c8159@1f1c794fb3c4.mail (4.3ms)
I, [2023-02-06T15:34:41.023900 #123]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [04d185a4-02d8-4823-b0e4-faf475e084ea] Performed ActionMailer::MailDeliveryJob (Job ID: 04d185a4-02d8-4823-b0e4-faf475e084ea) from Async(greenlight_v3_production_mailing) in 19.39ms
I, [2023-02-06T15:34:41.059760 #123]  INFO -- : [299ab5a3-3cf0-4071-8489-33e7985fca9a] Started GET "/api/v1/sessions.json" for 46.142.xxx.xxx at 2023-02-06 15:34:41 +0000
I, [2023-02-06T15:34:41.060401 #123]  INFO -- : [299ab5a3-3cf0-4071-8489-33e7985fca9a] Processing by Api::V1::SessionsController#index as JSON
I, [2023-02-06T15:34:41.062380 #123]  INFO -- : [299ab5a3-3cf0-4071-8489-33e7985fca9a] [active_model_serializers] Rendered ActiveModel::Serializer::Null with Hash (0.06ms)
I, [2023-02-06T15:34:41.062583 #123]  INFO -- : [299ab5a3-3cf0-4071-8489-33e7985fca9a] Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.4ms | Allocations: 553)
I, [2023-02-06T15:34:41.112696 #123]  INFO -- : [ceed6902-bd39-43de-a826-d940b9080eea] Started GET "/api/v1/site_settings.json?names=BrandingImage" for 46.142.xxx.xxx at 2023-02-06 15:34:41 +0000
I, [2023-02-06T15:34:41.115374 #123]  INFO -- : [ceed6902-bd39-43de-a826-d940b9080eea] Processing by Api::V1::SiteSettingsController#index as JSON
I, [2023-02-06T15:34:41.115531 #123]  INFO -- : [ceed6902-bd39-43de-a826-d940b9080eea]   Parameters: {"names"=>"BrandingImage"}
I, [2023-02-06T15:34:41.125433 #123]  INFO -- : [ceed6902-bd39-43de-a826-d940b9080eea] [active_model_serializers] Rendered ActiveModel::Serializer::Null with Hash (0.28ms)
I, [2023-02-06T15:34:41.125940 #123]  INFO -- : [ceed6902-bd39-43de-a826-d940b9080eea] Completed 200 OK in 10ms (Views: 1.8ms | ActiveRecord: 2.1ms | Allocations: 832)

And here the smtp part from .env. (anonymized too)

SMTP_SENDER_EMAIL=noreply@my.domain
SMTP_SENDER_NAME=Big Blue Button
SMTP_SERVER=my.mailserver
SMTP_PORT=587
SMTP_DOMAIN=my.bbb.domain
SMTP_USERNAME=
SMTP_PASSWORD=
SMTP_AUTH=
SMTP_STARTTLS_AUTO=true

Username and password I tried. But this makes no difference. My mailserver does not need auth. I allowed the bbb ip to mail.

thanks! t.

@farhatahmad
Copy link
Collaborator

I, [2023-02-06T15:34:41.022167 #123] INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [04d185a4-02d8-4823-b0e4-faf475e084ea] Delivered mail 63e11e1148e1_7ba30c8159@1f1c794fb3c4.mail (4.3ms)

As far as Greenlight is concered, the email was sent. Can you check your spam and your SMTP server to see if potentially it was blocked there?

@himpierre
Copy link
Author

I tried telnet from within the greenlight docker container and this worked.

ash-5.1# telnet mail.my.domain 587
Connected to mail.my.domain
ehlo mail
220 mail.my.domain ESMTP Exim 4.94.2 Mon, 06 Feb 2023 22:34:03 +0100
250-mail.my.domain Hello ip.ip-redacted.eu [54.37.xxx.xxx]
250-SIZE 52428800
250-8BITMIME
250-PIPELINING
250-PIPE_CONNECT
250-CHUNKING
250-STARTTLS
250 HELP
mail from: noreply@bbb.domain
250 OK
rcpt to: user@my.domain
250 Accepted
data
354 Enter message, ending with "." on a line by itself
subject: test
hallo
.
250 OK id=1pP98K-0004ls-9m

So there seems to be no network or other problem. The mailserver is under my control. There is no connection attempt when greenlight is sending mail although greenlight says so. How can I debug this further?

cheers, t.

@farhatahmad
Copy link
Collaborator

Honestly, I'm not quite sure at this point. From Greenlight's perspective, the email was sent. Assuming you've configured your .env variables correctly and restarted Greenlight after the changes, then the only explanation is your SMTP server stopping the email from being sent

@himpierre
Copy link
Author

himpierre commented Feb 7, 2023 via email

@farhatahmad
Copy link
Collaborator

Try completely removing SMTP_USERNAME, SMTP_PASSWORD, and SMTP_AUTH

@himpierre
Copy link
Author

himpierre commented Feb 7, 2023 via email

@himpierre
Copy link
Author

After further testing I found out that even with this entries in .env:

### SMTP CONFIGURATION
# Emails are required for the basic features of Greenlight to function.
# Please refer to your SMTP provider to get the values for the variables below
SMTP_SENDER_EMAIL=
SMTP_SENDER_NAME=
SMTP_SERVER=
SMTP_PORT=
SMTP_DOMAIN=
SMTP_USERNAME=
SMTP_PASSWORD=
SMTP_AUTH=
#SMTP_STARTTLS_AUTO=true
#SMTP_STARTTLS=false
#SMTP_TLS=false
#SMTP_SSL_VERIFY=true

I get this in the logs:

I, [2023-02-08T10:45:42.026517 #122]  INFO -- : [331ab041-eb3f-4be8-a143-921f3d3e5324] Started POST "/api/v1/reset_password.json" for 92.206.xxx.xxx at 2023-02-08 10:45:42 +0000
I, [2023-02-08T10:45:42.032899 #122]  INFO -- : [331ab041-eb3f-4be8-a143-921f3d3e5324] Processing by Api::V1::ResetPasswordController#create as JSON
I, [2023-02-08T10:45:42.033159 #122]  INFO -- : [331ab041-eb3f-4be8-a143-921f3d3e5324]   Parameters: {"user"=>{"email"=>"me@my.email.com"}, "reset_password"=>{"user"=>{"email"=>"me@my.email.com"}}}
I, [2023-02-08T10:45:42.048867 #122]  INFO -- : [331ab041-eb3f-4be8-a143-921f3d3e5324] [active_model_serializers] Rendered ActiveModel::Serializer::Null with Hash (0.14ms)
I, [2023-02-08T10:45:42.049574 #122]  INFO -- : [331ab041-eb3f-4be8-a143-921f3d3e5324] Completed 200 OK in 16ms (Views: 2.5ms | ActiveRecord: 5.4ms | Allocations: 1409)

So this messages do not mean very much.

Is the location ~/greenlight-v3/.env even right?

cheers, t.

@farhatahmad
Copy link
Collaborator

Here's what I have locally (not recommended for production)

SMTP_SENDER_EMAIL=ahmad.farhat@blindsidenetworks.com
SMTP_SENDER_NAME=BigBlueButton
SMTP_SERVER=smtp.gmail.com
SMTP_PORT=587
SMTP_DOMAIN=blindsidenetworks.com
SMTP_USERNAME=*************
SMTP_PASSWORD=**************
SMTP_AUTH=plain
SMTP_STARTTLS_AUTO=true
SMTP_STARTTLS=false
SMTP_TLS=false
SMTP_SSL_VERIFY=false

@farhatahmad
Copy link
Collaborator

Are you sure you're restarting Greenlight after making .env changes?

@himpierre
Copy link
Author

himpierre commented Feb 9, 2023 via email

@himpierre
Copy link
Author

I started from scratch completely. Same outcome. Strange. This is of course a dev system. If you like to have a look, I can put your public ssh-key on that machine.

cheers, t.

@farhatahmad
Copy link
Collaborator

Can you try using another SMTP server? Maybe a google one through gmail?

@himpierre
Copy link
Author

Tried my gmail account. Same thing. I guess for some reason the $SMTP values are not processed because as I said even with empty values success messages appear in the docker logs.

@farhatahmad
Copy link
Collaborator

The success logs you sent are related to the controller itself - not the actual sending of an email -> This is the log related to emails that you need to see:

I, [2023-02-06T15:34:41.022167 https://github.com//pull/123] INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [04d185a4-02d8-4823-b0e4-faf475e084ea] Delivered mail 63e11e1148e1_7ba30c8159@1f1c794fb3c4.mail (4.3ms)

@farhatahmad
Copy link
Collaborator

Try doing the following:

Set your .env values back to their expected values

docker exec -it greenlight-v3 bash
cd greenlight-v3
nano config/environments/production.rb

Go to line 73 and replace config.action_mailer.raise_delivery_errors = false with config.action_mailer.raise_delivery_errors = true
Save and exit nano

rails restart

Try to send an email while watchingthe logs

@himpierre
Copy link
Author

Now I get:

E, [2023-02-10T15:42:49.965077 #123] ERROR -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [bfa03dc6-d7d8-495e-8378-d0a540650a64] Error performing ActionMailer::MailDeliveryJob (Job ID: bfa03dc6-d7d8-495e-8378-d0a540650a64) from Async(greenlight_v3_production_mailing) in 17.35ms: ArgumentError (wrong authentication type ):
/usr/lib/ruby/gems/3.1.0/gems/net-smtp-0.3.1/lib/net/smtp.rb:859:in `check_auth_method'
/usr/lib/ruby/gems/3.1.0/gems/net-smtp-0.3.1/lib/net/smtp.rb:636:in `do_start'
/usr/lib/ruby/gems/3.1.0/gems/net-smtp-0.3.1/lib/net/smtp.rb:604:in `start'
/usr/lib/ruby/gems/3.1.0/gems/mail-2.7.1/lib/mail/network/delivery_methods/smtp.rb:109:in `start_smtp_session'
/usr/lib/ruby/gems/3.1.0/gems/mail-2.7.1/lib/mail/network/delivery_methods/smtp.rb:100:in `deliver!'
/usr/lib/ruby/gems/3.1.0/gems/mail-2.7.1/lib/mail/message.rb:2159:in `do_delivery'
/usr/lib/ruby/gems/3.1.0/gems/mail-2.7.1/lib/mail/message.rb:260:in `block in deliver'
...

Setting SMTP_AUTH now...stay tuned.

@himpierre
Copy link
Author

Now we have a read timeout.

E, [2023-02-10T15:48:03.059711 #128] ERROR -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [3fe98177-e889-4afa-be01-fa2962bbf2c2] Error performing ActionMailer::MailDeliveryJob (Job ID: 3fe98177-e889-4afa-be01-fa2962bbf2c2) from Async(greenlight_v3_production_mailing) in 5085.43ms: Net::ReadTimeout (Net::ReadTimeout with #<Socket:(closed)>):

Whats that suppose to mean?

@farhatahmad
Copy link
Collaborator

Cna you send me your SMTP settings (with things blanked out)

@himpierre
Copy link
Author

SMTP_SENDER_EMAIL=noreply@letsmeet.my.domain
SMTP_SENDER_NAME=BigBlueButton
SMTP_SERVER=mail.my.mailserver
SMTP_PORT=587
SMTP_DOMAIN=letsmeet.mydomain
SMTP_USERNAME=username
SMTP_PASSWORD=password
SMTP_AUTH=plain
SMTP_STARTTLS_AUTO=true
#SMTP_STARTTLS=false
#SMTP_TLS=false
#SMTP_SSL_VERIFY=false

@farhatahmad
Copy link
Collaborator

Try setting SMTP_TLS=true (making sure to remove the # before

@himpierre
Copy link
Author

Yeah, this cannot work.

E, [2023-02-10T16:48:18.359199 #128] ERROR -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [f49b828b-2e89-46e9-8d2d-c513154fe94d] Error performing ActionMailer::MailDeliveryJob (Job ID: f49b828b-2e89-46e9-8d2d-c513154fe94d) from Async(greenlight_v3_production_mailing) in 5303.22ms: Net::OpenTimeout (Net::OpenTimeout):

I'll try all possible settings now and get back to you. Thanks for the debug commands.

@farhatahmad
Copy link
Collaborator

I'm working on a configuration check task that should make your life easier if you can wait a few hours

@bayden10
Copy link

Just a quick chime in, I'm sure this is on your roadmap but yes it would be nice if SMTP settings could be managed within GL Administration were as soon as you change Registration Method to Approve/Decline or force apply SMTP setup you should then be prompted for settings.

Maybe also offer a test send button after docker has reloaded when save/update is exec.

@farhatahmad
Copy link
Collaborator

@himpierre There is a new configuration rake task with the latest beta of Greenlight. First upgrade Greenlight, then run docker exec -it greenlight-v3 bundle exec rake configuration:check. Let me know what it outputs

@bayden10 That's a bit tricky. Rails requires a full restart to apply the mailer changes, which is why they can't be fields in the UI. There are a few changes we need to make in terms of feedback to the user when choosing an option that requires SMTP

@himpierre
Copy link
Author

Check command gives me:

root@letsmeet:~/greenlight-v3# docker exec -it greenlight-v3 bundle exec rake configuration:check
Checking required environment variables:
Passed
Checking connection to Postgres Database:
Passed
Checking connection to Redis Cache:
Passed
Checking connection to BigBlueButton:
Failed - Could not get a valid response from BigBlueButton server - <Map><timestamp>1676400368078</timestamp><status>404</status><error>Not Found</error><path>/bigbluebutton/apigetMeetings</path></Map>
root@letsmeet:~/greenlight-v3# 

Thanks for leaving the debug option to true. Still not able to send mail though. Will try tomorrow a bit more.

cheers, t.

@bayden10
Copy link

yup, I get the same issue when running configuration:check

@farhatahmad
Copy link
Collaborator

farhatahmad commented Feb 14, 2023

Add a /api/ at the end the end of BIGBLUEBUTTON_ENDPOINT in the .env - I'll fix the script to factor that in

@himpierre
Copy link
Author

Does mailing work for you @bayden10? If so, what's your mail server setup?

cheers, t.

@himpierre
Copy link
Author

Started exim in debug mode. This is what I get:

22809 Listening...
22809 Connection request from 54.37.xxx.xxx port 41978
22809 search_tidyup called
22809 daemon forking for daemon-accept
22809 daemon forked for daemon-accept: 22828
22809 1 SMTP accept process running
22809 Listening...
22828 postfork: daemon-accept
22828 host in rfc1413_hosts? yes (matched "*")
22828 doing ident callback
22828  TFO mode sendto, with data: EINPROGRESS
22828 ident connection to 54.37.xxx.xxx failed: Connection timed out
22828 sender_fullhost = [54.37.xxx.xxx]
22828 sender_rcvhost = [54.37.xxx.xxx]
22828 Process 22828 is handling incoming connection from [54.37.xxx.xxx]
22828 checking for IP options
22828 no IP options found
22828 host in host_lookup? yes (matched "*")
22828 looking up host name for 54.37.xxx.xxx
22828 DNS lookup of xxx.xxx.37.54.in-addr.arpa (PTR) succeeded
22828 Reverse DNS security status: unverified
22828 IP address lookup yielded "letsmeet.greenlight.host"
22828 DNS lookup of letsmeet.greenlight.host (A) succeeded
22828 letsmeet.greenlight.host 54.37.xxx.xxx mx=-1 sort=-113 
22828 checking addresses for letsmeet.greenlight.host
22828 Forward DNS security status: unverified
22828   54.37.xxx.xxx OK
22828 sender_fullhost = letsmeet.greenlight.host [54.37.xxx.xxx]
22828 sender_rcvhost = letsmeet.greenlight.host ([54.37.xxx.xxx])
22828 set_process_info: 22828 handling incoming connection from letsmeet.greenlight.host [54.37.xxx.xxx]
22828 host in host_reject_connection? no (option unset)
22828 host in sender_unqualified_hosts? no (option unset)
22828 host in recipient_unqualified_hosts? no (option unset)
22828 host in helo_verify_hosts? no (option unset)
22828 host in helo_try_verify_hosts? no (option unset)
22828 host in helo_accept_junk_hosts? no (option unset)
22828 host in pipelining_connect_advertise_hosts? yes (matched "*")
22828 SMTP>> 220 mail.my.mail.server ESMTP Exim 4.94.2 Wed, 15 Feb 2023 11:03:06 +0100
22828 TCP_INFO getsockopt: Success
22828 Process 22828 is ready for new message
22828 smtp_setup_msg entered
22828 SMTP>> 421 mail.my.mail.server lost input connection
22828 LOG: smtp_connection MAIN
22828   SMTP connection from letsmeet.greenlight.host [54.37.xxx.xxx] lost D=0s
22828 search_tidyup called
22828 SMTP>>(close on process exit)
22828 >>>>>>>>>>>>>>>> Exim pid=22828 (daemon-accept) terminating with rc=1 >>>>>>>>>>>>>>>>
22809 child 22828 ended: status=0x100
22809   normal exit, 1
22809 0 SMTP accept processes now running
22809 Listening...
^C22809 SIGTERM/SIGINT seen
22809 daemon forking for daemon-del-pidfile
22809 daemon forked for daemon-del-pidfile: 22832
22832 postfork: daemon-del-pidfile
22832 exec /usr/sbin/exim -d=0xf7795cfd -MCd daemon-del-pidfile -oPX
22809 search_tidyup called
22809 >>>>>>>>>>>>>>>> Exim pid=22809 (daemon) terminating with rc=0 >>>>>>>>>>>>>>>>

So greenlight just drops the connection. I'm out of ideas here.

@farhatahmad
Copy link
Collaborator

Can you run the configuration check command again

@himpierre
Copy link
Author

himpierre commented Feb 15, 2023

root@letsmeet:~/greenlight-v3# docker exec -it greenlight-v3 bundle exec rake configuration:check
Checking required environment variables:
Passed
Checking connection to Postgres Database:
Passed
Checking connection to Redis Cache:
Passed
Checking connection to BigBlueButton:
Passed
Checking connection to SMTP Server
I, [2023-02-15T15:46:30.800671 #133]  INFO -- :   Rendered user_mailer/test_email.html.erb within layouts/mailer (Duration: 0.5ms | Allocations: 415)
I, [2023-02-15T15:46:30.801483 #133]  INFO -- :   Rendered layout layouts/mailer.html.erb (Duration: 1.4ms | Allocations: 801)
I, [2023-02-15T15:46:30.802103 #133]  INFO -- :   Rendered user_mailer/test_email.text.erb within layouts/mailer (Duration: 0.3ms | Allocations: 170)
I, [2023-02-15T15:46:30.802659 #133]  INFO -- :   Rendered layout layouts/mailer.text.erb (Duration: 0.8ms | Allocations: 291)
I, [2023-02-15T15:46:35.838715 #133]  INFO -- : Delivered mail 63ecfe56c4b2e_8514502232@bbd484d6ab3c.mail (5034.1ms)
Failed - Unable to connect to SMTP Server - Net::ReadTimeout
root@letsmeet:~/greenlight-v3# 

Net::ReadTimeout is very strange. I tried delivering a mail via telnet from within the docker container and it worked. I don't know why ruby fails. Like they don't understand each other.

@farhatahmad
Copy link
Collaborator

We can go through a few troubleshooting steps 1 by 1.
Set SMTP_TLS=true and re-run the config

@himpierre
Copy link
Author

himpierre commented Feb 15, 2023

Progress! I need to open port 113 and port 25 (iptables) on the greenlight machine. That's kinda odd.

(maybe the bbb-install-2.6.sh script forgets to set the statefull firewall rules?)

@bayden10
Copy link

bayden10 commented Feb 15, 2023

@himpierre , been busy but port 113? does this mean port forwarding is required for NATed hosts?

Still an issue

Docker Log

`
greenlight-v3 | I, [2023-02-15T16:30:48.569612 #129] INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [a4381605-d577-4c7c-aa80-3d5faa1d994a] Delivered mail 63ed08b86c547_819a744922@b9b8e7de58d8.mail (126.8ms)

greenlight-v3 | E, [2023-02-15T16:30:48.569965 #129] ERROR -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [a4381605-d577-4c7c-aa80-3d5faa1d994a] Error performing ActionMailer::MailDeliveryJob (Job ID: a4381605-d577-4c7c-aa80-3d5faa1d994a) from Async(greenlight_v3_production_mailing) in 152.87ms: OpenSSL::SSL::SSLError (SSL_connect returned=1 errno=0 peeraddr=x.x.x.x:587 state=error: wrong version number):

`

Config Check

`
Checking connection to SMTP Server
I, [2023-02-15T16:32:17.654379 #142] INFO -- : Rendered user_mailer/test_email.html.erb within layouts/mailer (Duration: 1.3ms | Allocations: 416)
I, [2023-02-15T16:32:17.655645 #142] INFO -- : Rendered layout layouts/mailer.html.erb (Duration: 2.7ms | Allocations: 802)
I, [2023-02-15T16:32:17.656869 #142] INFO -- : Rendered user_mailer/test_email.text.erb within layouts/mailer (Duration: 0.5ms | Allocations: 171)
I, [2023-02-15T16:32:17.657447 #142] INFO -- : Rendered layout layouts/mailer.text.erb (Duration: 1.2ms | Allocations: 292)
I, [2023-02-15T16:32:17.905991 #142] INFO -- : Delivered mail 63ed0911a22af_8e1450385a0@b9b8e7de58d8.mail (243.9ms)
Failed - Unable to connect to SMTP Server - SSL_connect returned=1 errno=0 peeraddr=x.x.x.x:587 state=error: wrong version number

`

my config

`
SMTP_SENDER_EMAIL=admin@domain.ca
SMTP_SENDER_NAME=noreply
SMTP_SERVER=mail.domain.ca
SMTP_PORT=587
SMTP_DOMAIN=domain.ca
SMTP_USERNAME=conf@domain.ca
SMTP_PASSWORD=password
SMTP_AUTH=PLAIN
SMTP_STARTTLS_AUTO=true
SMTP_STARTTLS=true
SMTP_TLS=true
#SMTP_SSL_VERIFY=false

`
Does not attempt to connect after failing TLS. Firewall is disabled.

@farhatahmad
Copy link
Collaborator

@bayden10 uncomment #SMTP_SSL_VERIFY=false

@bayden10
Copy link

same:

I, [2023-02-15T16:45:54.239437 #10] INFO -- : Delivered mail 63ed0c42f47a_a1450-319@bc17d5e5d4bf.mail (183.6ms) Failed - Unable to connect to SMTP Server - SSL_connect returned=1 errno=0 peeraddr=x.x.x.x:587 state=error: wrong version number

@himpierre
Copy link
Author

Yeah. Somehow the new greenlight version needs to be reached from outside when sending mail. I guess that's new? In fact until now I never had to fiddle with firewall settings.

@bayden10
Copy link

@himpierre are you behind NAT?

@himpierre
Copy link
Author

himpierre commented Feb 15, 2023 via email

@himpierre
Copy link
Author

Alright. To summarize things up. The main reason mailing did not work was this. My mailserver tries to contact the connecting server on port 113 when there is authentication involved. Timeout was 5s. This is obviousely to long for the ruby process on the greenlight machine and ruby hangs up. After I disabled that lookup no firewall rules are needed anymore and all works as expected.

Remaining question @farhatahmad: It does not seem to be possible to not enter credentials in the mail settings. So we are forced to use authentication. I would prefer to just let the greenlight machine mail along without authentication by accepting mails from their ip address. Could you please have a look at this?

cheers, t.

@farhatahmad
Copy link
Collaborator

We'll make a change to allow Greenlight to connect to SMTP without authentication

@amg-web
Copy link

amg-web commented Feb 28, 2023

@himpierre , @farhatahmad
I just uncommented login and password lines without assining anything there. it worked for the server without authentification

I was sure it was working
I can not get it work now.

@himpierre
Copy link
Author

himpierre commented Feb 28, 2023 via email

@emanuelalmeidaa
Copy link

SOLVED using this #1574

@b01xy
Copy link

b01xy commented Sep 21, 2023

Hello @himpierre @farhatahmad

we encountered the same issue here #5400 which since then has evolved also to a time out issue with this .env config

### SMTP CONFIGURATION
# Emails are required for the basic features of Greenlight to function.
# Please refer to your SMTP provider to get the values for the variables below
SMTP_SENDER_EMAIL=febot@mondomain.fr
SMTP_SENDER_NAME=Monprojet
SMTP_SERVER=mail.infomaniak.com
SMTP_PORT=465
SMTP_DOMAIN=mondomain.fr
SMTP_USERNAME=febot@mondomain.fr
SMTP_PASSWORD=monpassword
SMTP_AUTH=PLAIN
SMTP_STARTTLS_AUTO=true
#SMTP_STARTTLS=true
#SMTP_TLS=true
SMTP_SSL_VERIFY=true

I'm able to send mail via this infomaniak smtp from the server with an openssl command (couldn't try from the docker itself as I don't think openssl or telnet command exist in the container)

...
Checking connection to BigBlueButton:
Passed
Checking connection to SMTP Server
I, [2023-09-21T23:32:02.098748 #10]  INFO -- : Delivered mail 650cd26d43ae_a13388404d@0e5986d62653.mail (5082.1ms)
Failed - Unable to connect to SMTP Server - Net::ReadTimeout

as far as I understood the exchange, do you think we should create a firewall rule to drive a reply from the smtp server to greenlight docker internal ip to finish the authentication mechanism and avoid the time out ? In this case what should be this port ?

any advice would be super welcome as we are now a bit clueless !
thanks

@plastilincheg
Copy link
Contributor

plastilincheg commented Mar 31, 2024

Hello Faced with a similar problem. When you try to send an invitation, the system does not manage, does not send any connections to the mail server, checked for 2 different smtp. I have a dedicated server for BBB with an external IP.

Ubuntu 22.04.4 LTS
Greenlight release-3.3.1

Tried turning off UFW - it didn't help. Is there any solution?
I am using an authenticated SMTP connection. Also if you execute the command

docker logs greenlight-v3

It can be seen that the token is generated, and if you copy it manually and paste it in the browser, you can complete the registration.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants