Plots2: Email notifications cause error on new note creation

Created on 5 Jul 2018  ยท  36Comments  ยท  Source: publiclab/plots2

I just tried posting a new note at /post, but got a 500 error, with the log message:

[ae40c547-65a0-441d-a855-604ed50dad01]   Rendering subscription_mailer/notify_node_creation.html.erb
[ae40c547-65a0-441d-a855-604ed50dad01]   Rendered subscription_mailer/notify_node_creation.html.erb (30.8ms)
[ae40c547-65a0-441d-a855-604ed50dad01] Sent mail to [email protected] (98.7ms)
[ae40c547-65a0-441d-a855-604ed50dad01] Completed 500 Internal Server Error in 320ms (ActiveRecord: 88.0ms)
[ae40c547-65a0-441d-a855-604ed50dad01]   
[ae40c547-65a0-441d-a855-604ed50dad01] SocketError (getaddrinfo: Name or service not known):
[ae40c547-65a0-441d-a855-604ed50dad01]   
[ae40c547-65a0-441d-a855-604ed50dad01] app/models/node.rb:204:in `notify'
[ae40c547-65a0-441d-a855-604ed50dad01] app/models/node.rb:635:in `block in new_note'
[ae40c547-65a0-441d-a855-604ed50dad01] app/models/node.rb:619:in `new_note'
[ae40c547-65a0-441d-a855-604ed50dad01] app/controllers/notes_controller.rb:109:in `create'

I think this is related to the mail server it's trying to connect to? @icarito and @namangupta01 could you take a look? Thanks!

bug

Most helpful comment

Great @namangupta01 I've added docker-compose exec -T mailman bash -c "echo 172.19.0.1 smtp >> /etc/hosts" to Makefile in #3000.

Congrats on a work well done and thank you!

All 36 comments

It's possible one of hte "everyone" subscribers has a bad email address, and they're all BCC'ed on the notification we're trying to send -- see

https://github.com/publiclab/plots2/blob/4633adf69aa3f3a6a421765ff2ef9cd4b92209aa/app/mailers/subscription_mailer.rb#L12-L16

But i'm not sure that'd cause this?

I got a similar socket error when tried digest email. I guess it be still available on sidekiq dashboard on unstable. unstable.publiclab.org/sidekiq

@jywarren last night I was implementing https://github.com/publiclab/plots2/pull/2979 in production and I missed step that sets up the link to SMTP with https://github.com/publiclab/plots2/blob/master/Makefile#L16 - I did these steps now, and confirmed SMTP server is reachable from production container.

I believe this is fixed. Apologies - this was caused by missing a deployment step during working on our deployment script.

I am getting error something went wrong when i am adding comment
https://publiclab.org/notes/namangupta/02-17-2018/gsoc-proposal and when i refresh the page comment is there so i guess the comment is saving properly but the notify thing we do after saving causing problem. And also i tried to add comment by reply by mail and i am not seeing that added too... @jywarren can you please share the logs ?
@ViditChitkara Does it have anything to do with side-kiq --the notify thing?

screen shot 2018-07-06 at 2 37 27 pm

Hmm, yes, i'm also still seeing a 500 error when publishing from /post. But spammers have been able to... the logic for their posting is a little different. I'll check the logs again but this is still pretty urgent!

I think this has do with sidekiq- queue but i am not sure.

On Fri, Jul 6, 2018 at 7:09 PM Jeffrey Warren notifications@github.com
wrote:

Hmm, yes, i'm also still seeing a 500 error when publishing from /post.
But spammers have been able to... the logic for their posting is a little
different. I'll check the logs again but this is still pretty urgent!

โ€”
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/publiclab/plots2/issues/2989#issuecomment-403037109,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ATwCYdATdb_xHViDt1EUVLPQYyVGKf51ks5uD2h7gaJpZM4VElMd
.

And please also share mailman log

@jywarren can you share the logs. @namangupta01 the latest sidekiq related changes have not been published yet. Searching this out.

I just checked mailman logs, found this:

icarito@rs-plots2:/srv/plots_container/plots2$ docker-compose logs mailman
Attaching to containers_mailman_1
mailman_1  | /usr/local/bundle/gems/activerecord-5.2.0/lib/active_record/associations/builder/collection_association.rb:27: warning: already initialized constant TagNodeAssociationExtension
mailman_1  | /usr/local/bundle/gems/activerecord-5.2.0/lib/active_record/associations/builder/collection_association.rb:27: warning: previous definition of TagNodeAssociationExtension was here
mailman_1  | /usr/local/lib/ruby/2.4.0/net/pop.rb:1006:in `check_response_auth': -ERR [SYS/TEMP] Temporary system problem. Please try again later. (Net::POPAuthenticationError)
mailman_1  |    from /usr/local/lib/ruby/2.4.0/net/pop.rb:905:in `auth'
mailman_1  |    from /usr/local/lib/ruby/2.4.0/net/pop.rb:567:in `do_start'
mailman_1  |    from /usr/local/lib/ruby/2.4.0/net/pop.rb:537:in `start'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/receiver/pop3.rb:31:in `connect'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:132:in `block in polling_loop'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:130:in `loop'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:130:in `polling_loop'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:83:in `run'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:11:in `run'
mailman_1  |    from script/mailman_server:22:in `<main>'
mailman_1  | /usr/local/bundle/gems/activerecord-5.2.0/lib/active_record/associations/builder/collection_association.rb:27: warning: already initialized constant TagNodeAssociationExtension
mailman_1  | /usr/local/bundle/gems/activerecord-5.2.0/lib/active_record/associations/builder/collection_association.rb:27: warning: previous definition of TagNodeAssociationExtension was here
mailman_1  | /usr/local/lib/ruby/2.4.0/net/pop.rb:1006:in `check_response_auth': -ERR [SYS/TEMP] Temporary system problem. Please try again later. (Net::POPAuthenticationError)
mailman_1  |    from /usr/local/lib/ruby/2.4.0/net/pop.rb:905:in `auth'
mailman_1  |    from /usr/local/lib/ruby/2.4.0/net/pop.rb:567:in `do_start'
mailman_1  |    from /usr/local/lib/ruby/2.4.0/net/pop.rb:537:in `start'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/receiver/pop3.rb:31:in `connect'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:132:in `block in polling_loop'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:130:in `loop'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:130:in `polling_loop'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:83:in `run'
mailman_1  |    from /usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:11:in `run'
mailman_1  |    from script/mailman_server:22:in `<main>'

I found the mailman container down, and started it. The error above appeared, but mailman appears to be running now. I'll try to reproduce to confirm if error persists.

Okay I'm seeing this in production.log:

[3ab23bcf-eb48-4c08-92f5-bff279577fb1] Started POST "/comment/create/15755" for 200.121.203.242 at 2018-07-06 17:20:13 +0000
[3ab23bcf-eb48-4c08-92f5-bff279577fb1] Processing by CommentController#create as JS
[3ab23bcf-eb48-4c08-92f5-bff279577fb1]   Parameters: {"body"=>"Mailman was down, I started it! I wonder if it crashed, will try to find it in the logs.", "id"=>"15755"}
[3ab23bcf-eb48-4c08-92f5-bff279577fb1]   Rendering comment_mailer/notify_note_author.html.erb                                     [3ab23bcf-eb48-4c08-92f5-bff279577fb1]   Rendered comment_mailer/notify_note_author.html.erb (8.1ms)                              [3ab23bcf-eb48-4c08-92f5-bff279577fb1] Sent mail to [email protected] (209.5ms)
[3ab23bcf-eb48-4c08-92f5-bff279577fb1] Completed 500 Internal Server Error in 252ms (ActiveRecord: 16.1ms)                        [3ab23bcf-eb48-4c08-92f5-bff279577fb1]                                                                                            [3ab23bcf-eb48-4c08-92f5-bff279577fb1] Net::SMTPFatalError (550 relay not permitted
):
[3ab23bcf-eb48-4c08-92f5-bff279577fb1]                                                                                            [3ab23bcf-eb48-4c08-92f5-bff279577fb1] app/models/comment.rb:152:in `notify'
[3ab23bcf-eb48-4c08-92f5-bff279577fb1] app/helpers/comment_helper.rb:8:in `create_comment'                                        [3ab23bcf-eb48-4c08-92f5-bff279577fb1] app/controllers/comment_controller.rb:21:in `create'

This has to do with #2979 - seems I need to authorize local email relay from the internal docker address. I'll fix it, sorry!

Indeed, with changes in #2979, plots is running now from an internal IP address and we needed to tell exim4 about relaying mail from Docker's internal IP.

It would be good to have an exim4 container for SMTP within our compose file so that we can have that part of the configuration visible as well.

I just tested this and it is fixed!

@icarito can you please also share the logs logs/mailman.log? Which could give us some more detail?

Here's fragments:

/usr/local/lib/ruby/2.4.0/net/smtp.rb:539:in `initialize'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:539:in `open'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:539:in `tcp_socket'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:549:in `block in do_start'
/usr/local/lib/ruby/2.4.0/timeout.rb:93:in `block in timeout'
/usr/local/lib/ruby/2.4.0/timeout.rb:103:in `timeout'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:548:in `do_start'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:518:in `start'
/usr/local/bundle/gems/mail-2.7.0/lib/mail/network/delivery_methods/smtp.rb:109:in `start_smtp_session'
/usr/local/bundle/gems/mail-2.7.0/lib/mail/network/delivery_methods/smtp.rb:100:in `deliver!'
/usr/local/bundle/gems/mail-2.7.0/lib/mail/message.rb:2160:in `do_delivery'
/usr/local/bundle/gems/mail-2.7.0/lib/mail/message.rb:260:in `block in deliver'
/usr/local/bundle/gems/actionmailer-5.2.0/lib/action_mailer/base.rb:560:in `block in deliver_mail'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/notifications.rb:168:in `block in instrument'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/notifications.rb:168:in `instrument'
/usr/local/bundle/gems/actionmailer-5.2.0/lib/action_mailer/base.rb:558:in `deliver_mail'
/usr/local/bundle/gems/mail-2.7.0/lib/mail/message.rb:260:in `deliver'
/usr/local/bundle/gems/actionmailer-5.2.0/lib/action_mailer/message_delivery.rb:114:in `block in deliver_now'
/usr/local/bundle/gems/actionmailer-5.2.0/lib/action_mailer/rescuable.rb:17:in `handle_exceptions'
/usr/local/bundle/gems/actionmailer-5.2.0/lib/action_mailer/message_delivery.rb:113:in `deliver_now'
/app/app/models/comment.rb:152:in `notify'
/app/app/models/comment.rb:254:in `receive_mail'
script/mailman_server:27:in `block (2 levels) in <main>'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/router.rb:66:in `instance_exec'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/router.rb:66:in `route'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/message_processor.rb:23:in `block in process'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/middleware.rb:33:in `block in run'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/middleware.rb:38:in `run'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/message_processor.rb:22:in `process'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/receiver/pop3.rb:43:in `block in get_messages'
/usr/local/lib/ruby/2.4.0/net/pop.rb:666:in `each'
/usr/local/lib/ruby/2.4.0/net/pop.rb:666:in `each_mail'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/receiver/pop3.rb:42:in `get_messages'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:133:in `block in polling_loop'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:130:in `loop'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:130:in `polling_loop'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:83:in `run'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:11:in `run'
script/mailman_server:22:in `<main>'
I, [2018-07-06T17:14:57.814639 #1]  INFO -- : Got new message from '[email protected]' with subject 'Re: New comment on GSoC proposal: Email integration Project (#15755)'.
E, [2018-07-06T17:14:58.060304 #1] ERROR -- : Exception occurred while receiving message:
Return-Path: <[email protected]>^M
Received: by 2002:a67:7b15:0:0:0:0:0 with SMTP id w21-v6csp1462798vsc;=0D=0A  ^M
      Fri, 6 Jul 2018 01:57:10 -0700 (PDT)^M
Received: from mail-sor-f41.google.com (mail-sor-f41.google.com. [209.85.220.41])        by mx.google.com with SMTPS id o204-v6sor5647431oih.122.2018.07.06.01.57.10        for <[email protected]>        (Google Transport Security); Fri, 06 Jul 2018 01:57:10 -0700^M
Received: by 2002:a9d:4a2e:0:0:0:0:0 with HTTP; Fri, 6 Jul 2018 01:57:09 -0700^M
 (PDT)^M
Date: Fri, 06 Jul 2018 14:27:09 +0530^M
From: Naman Gupta <[email protected]>^M
To: [email protected]^M
Message-ID: <CAELvC+AD=bwDphABkAr=7_=b1vvzZ-734+YiXfr8C3LEmtWpRw@mail.gmail.com>^M
In-Reply-To: <CAELvC+BiH=FKMZ_eXbQ4CSFAmzmtM4Pnytb9TLB98nHeg+CLfQ@mail.gmail.com>^M
References: <[email protected]>^M
 <CAELvC+DYwnz=7Dm2cs3KEtkcwb7COgcvKx3VsLQxhVGpJdy3Wg@mail.gmail.com>^M
 <CAELvC+BiH=FKMZ_eXbQ4CSFAmzmtM4Pnytb9TLB98nHeg+CLfQ@mail.gmail.com>^M
Subject: Re: New comment on GSoC proposal: Email integration Project (#15755)^M
Mime-Version: 1.0^M
Content-Type: multipart/alternative;^M
 boundary=00000000000061c77f057050d9ef^M
Content-Transfer-Encoding: 7bit^M
Delivered-To: [email protected]^M
X-Received: by 2002:aca:e30b:: with SMTP id^M
 a11-v6mr9844293oih.303.1530867430865;        Fri, 06 Jul 2018 01:57:10 -0700^M
 (PDT)^M

< snip >


E, [2018-07-06T17:14:58.060500 #1] ERROR -- : getaddrinfo: Name or service not known
/usr/local/lib/ruby/2.4.0/net/smtp.rb:539:in `initialize'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:539:in `open'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:539:in `tcp_socket'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:549:in `block in do_start'
/usr/local/lib/ruby/2.4.0/timeout.rb:93:in `block in timeout'
/usr/local/lib/ruby/2.4.0/timeout.rb:103:in `timeout'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:548:in `do_start'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:518:in `start'
/usr/local/bundle/gems/mail-2.7.0/lib/mail/network/delivery_methods/smtp.rb:109:in `start_smtp_session'
/usr/local/bundle/gems/mail-2.7.0/lib/mail/network/delivery_methods/smtp.rb:100:in `deliver!'
/usr/local/bundle/gems/mail-2.7.0/lib/mail/message.rb:2160:in `do_delivery'
/usr/local/bundle/gems/mail-2.7.0/lib/mail/message.rb:260:in `block in deliver'
/usr/local/bundle/gems/actionmailer-5.2.0/lib/action_mailer/base.rb:560:in `block in deliver_mail'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/notifications.rb:168:in `block in instrument'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/notifications.rb:168:in `instrument'
/usr/local/bundle/gems/actionmailer-5.2.0/lib/action_mailer/base.rb:558:in `deliver_mail'
/usr/local/bundle/gems/mail-2.7.0/lib/mail/message.rb:260:in `deliver'
/usr/local/bundle/gems/actionmailer-5.2.0/lib/action_mailer/message_delivery.rb:114:in `block in deliver_now'
/usr/local/bundle/gems/actionmailer-5.2.0/lib/action_mailer/rescuable.rb:17:in `handle_exceptions'
/usr/local/bundle/gems/actionmailer-5.2.0/lib/action_mailer/message_delivery.rb:113:in `deliver_now'
/app/app/models/comment.rb:152:in `notify'
/app/app/models/comment.rb:254:in `receive_mail'
script/mailman_server:27:in `block (2 levels) in <main>'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/router.rb:66:in `instance_exec'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/router.rb:66:in `route'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/message_processor.rb:23:in `block in process'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/middleware.rb:33:in `block in run'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/middleware.rb:38:in `run'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/message_processor.rb:22:in `process'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/receiver/pop3.rb:43:in `block in get_messages'
/usr/local/lib/ruby/2.4.0/net/pop.rb:666:in `each'
/usr/local/lib/ruby/2.4.0/net/pop.rb:666:in `each_mail'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/receiver/pop3.rb:42:in `get_messages'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:133:in `block in polling_loop'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:130:in `loop'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:130:in `polling_loop'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:83:in `run'
/usr/local/bundle/gems/mailman-0.7.0/lib/mailman/application.rb:11:in `run'
script/mailman_server:22:in `<main>'

Does mailman need direct access to smtp? In that case we'll need to add a line like https://github.com/publiclab/plots2/blob/stable/Makefile#L16 to Makefile that adds the IP address for SMTP to the mailman container.

Hooray, my part no longer happens - the blog post published normally just now. Should we think about monitoring that process to check for downtime?

Maybe a /status route that we can check with the rackspace monitoring service?

@icarito @jywarren I still see this socket error on sidekiq dashboard (see https://unstable.publiclab.org/sidekiq/). Do we have to make some other settings for this?

Vidit I'm seeing this when trying to check container in unstable:


ERROR: The Compose file './containers/docker-compose-production.yml' is
invalid because:
services.mailman.environment contains non unique items, please remove
duplicates from [u'RAILS_ENV=', u'SECRET_KEY_BASE=', u'SERVER_ADDRESS=',
u'USERNAME=', u'EMAIL_PASSWORD=', u'SECRET_KEY_BASE=']

On 06/07/18 13:05, Vidit wrote:
>

@icarito https://github.com/icarito @jywarren
https://github.com/jywarren I still see this socket error on sidekiq
dashboard (see https://unstable.publiclab.org/sidekiq/). Do we have to
make some other settings for this?

โ€”
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/publiclab/plots2/issues/2989#issuecomment-403107433,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAMMS_YKsH8gsxnuurA9ArQR1Wdk7KrIks5uD6bagaJpZM4VElMd.

@icarito, since after adding the comment after reply by mail we need to send the email to the users so we need to have a access to the mail service.

I mean to say mailman needs to have access.

Above mailman logs are showing error while calling notify function which is used to send mails.

@ViditChitkara I've patched docker compose production yml with #3000, check docker-compose-unstable for the same fix. We should probably talk about it in the corresponding issue, not sure if one is open?

@namangupta01 okay I'm going to issue manually the following command:

docker-compose exec -T mailman bash -c "echo 172.19.0.1 smtp >> /etc/hosts"

If this makes it work, we will need to add this command next to https://github.com/publiclab/plots2/blob/stable/Makefile#L16

Also I think mailman container has a different ip as web container. Either I add that to exim relay ip list, or... we use network_mode: "service:web". I'll try the latter.

@namangupta01 I've updated PR #3000 hopefully solving this in production. Testing it!

@jywarren I cherrypicked both commits from #3000 to get mailman working in production. I just replied to notifications@ but I'm not sure it works? Let me know!

@icarito checking.

@icarito your comment shows in my note. It's working.

Yeah its working. @icarito Please have a look.

And also mails are also being sent on mailman incoming mails

Great @namangupta01 I've added docker-compose exec -T mailman bash -c "echo 172.19.0.1 smtp >> /etc/hosts" to Makefile in #3000.

Congrats on a work well done and thank you!

๐ŸŽ‰ ๐ŸŽ‰ Awesome Finally it worked. ๐ŸŽ‰ ๐ŸŽ‰

Was this page helpful?
0 / 5 - 0 ratings

Related issues

first-timers[bot] picture first-timers[bot]  ยท  3Comments

grvsachdeva picture grvsachdeva  ยท  3Comments

jywarren picture jywarren  ยท  3Comments

first-timers[bot] picture first-timers[bot]  ยท  3Comments

milaaraujo picture milaaraujo  ยท  3Comments