Email receiving (reply by email) not working intermittently

[jywarren]

I just confirmed this and we need to do a bit of investigation on this, cc @icarito @namangupta01 thanks!

[jywarren]

Hmm, I see 120 mailers enqueued, could it be related?

https://publiclab.org/sidekiq/queues

[jywarren]

anything show up in that log? Looking at this, it seems it would create an error if it failed:

plots2/script/mailman_server

Line 6 in 10dcec3

Mailman.config.logger = Logger.new("log/mailman.log")

[jywarren]

Noting:

I, [2019-04-30T23:17:30.422453 #1]  INFO -- : Mailman v0.7.0 started
I, [2019-04-30T23:17:30.422654 #1]  INFO -- : Rails root found in ., requiring environment...
I, [2019-04-30T23:17:51.441128 #1]  INFO -- : POP3 receiver enabled (notifications@publiclab.org@pop.gmail.com).
I, [2019-04-30T23:17:51.512210 #1]  INFO -- : Polling enabled. Checking every 5 seconds.

the place is /srv/plots_container/plots2/log/mailman.log

[jywarren]

OK, logs show:

I, [2019-05-07T18:27:01.901758 #1]  INFO -- : Got new message from 'notifications@publiclab.org' with subject '[PublicLab] What are some of the challenges of implementing a problem-based learning curriculum in your classroom? (#19267)'.
I, [2019-05-07T19:01:45.315583 #1]  INFO -- : Got new message from 'notifications@publiclab.org' with subject '[PublicLab] Map Knitter- UI Test , Ballon Mapping Test (#19266)'.
I, [2019-05-07T19:23:06.154395 #1]  INFO -- : Got new message from 'notifications@publiclab.org' with subject '[PublicLab] Workshop II: What Factors Influence Our Environmental Problem? (#19268)'.
I, [2019-05-07T19:47:19.795926 #1]  INFO -- : Got new message from 'notifications@publiclab.org' with subject 'How much helium do you need to fill a balloon in the regular balloon mapping kits?  (#19269)'.
I, [2019-05-07T19:47:19.870286 #1]  INFO -- : Got new message from 'notifications@publiclab.org' with subject 'How much helium do you need to fill a balloon in the regular balloon mapping kits?  (#19269)'.
I, [2019-05-07T19:47:19.948173 #1]  INFO -- : Got new message from 'notifications@publiclab.org' with subject 'How much helium do you need to fill a balloon in the regular balloon mapping kits?  (#19269)'.
I, [2019-05-07T19:47:20.019307 #1]  INFO -- : Got new message from 'notifications@publiclab.org' with subject 'How much helium do you need to fill a balloon in the regular balloon mapping kits?  (#19269)'.
I, [2019-05-07T19:47:41.852650 #1]  INFO -- : Got new message from 'notifications@publiclab.org' with subject '[PublicLab] How much helium do you need to fill a balloon in the regular balloon mapping kits?  (#19269)'.
I, [2019-05-07T20:11:34.578764 #1]  INFO -- : Got new message from 'notifications@publiclab.org' with subject '[PublicLab] Introducing a (draft) Style Guide for Public Lab (#19270)'.
I, [2019-05-07T22:43:18.137783 #1]  INFO -- : Mailman v0.7.0 started 
I, [2019-05-07T22:43:18.211389 #1]  INFO -- : Rails root found in ., requiring environment...
I, [2019-05-07T22:43:38.500466 #1]  INFO -- : POP3 receiver enabled (notifications@publiclab.org@pop.gmail.com).
I, [2019-05-07T22:43:38.526023 #1]  INFO -- : Polling enabled. Checking every 5 seconds.
I, [2019-05-07T23:02:00.256438 #1]  INFO -- : Mailman v0.7.0 started
I, [2019-05-07T23:02:00.267611 #1]  INFO -- : Rails root found in ., requiring environment...
I, [2019-05-07T23:02:15.111166 #1]  INFO -- : POP3 receiver enabled (notifications@publiclab.org@pop.gmail.com).
I, [2019-05-07T23:02:15.118063 #1]  INFO -- : Polling enabled. Checking every 5 seconds.
I, [2019-05-07T23:56:44.702410 #1]  INFO -- : Mailman v0.7.0 started
I, [2019-05-07T23:56:44.717554 #1]  INFO -- : Rails root found in ., requiring environment...
I, [2019-05-07T23:57:01.172414 #1]  INFO -- : POP3 receiver enabled (notifications@publiclab.org@pop.gmail.com).
I, [2019-05-07T23:57:01.179108 #1]  INFO -- : Polling enabled. Checking every 5 seconds.
I, [2019-05-08T11:53:47.196885 #1]  INFO -- : Got new message from 'xxxxxxxx@gmail.com' with subject 'Re: Welcome to Public Lab'.

aha:

I, [2019-05-06T19:45:06.843403 #1]  INFO -- : Mailman v0.7.0 started
I, [2019-05-06T19:45:06.852555 #1]  INFO -- : Rails root found in ., requiring environment...
I, [2019-05-06T19:45:24.062771 #1]  INFO -- : POP3 receiver enabled (notifications@publiclab.org@pop.gmail.com).
I, [2019-05-06T19:45:24.072338 #1]  INFO -- : Polling enabled. Checking every 5 seconds.
I, [2019-05-06T21:19:41.081599 #1]  INFO -- : Got new message from 'mailer-daemon@googlemail.com' with subject 'Delivery Status Notification (Failure)'
.
I, [2019-05-06T22:54:48.680320 #1]  INFO -- : Got new message from 'jeff@publiclab.org' with subject 'Re: New comment on A big WELCOME to our Outreachy
/GSoC team for 2019! (#19259)'.

[jywarren]

I, [2019-05-06T21:19:41.081599 #1] INFO -- : Got new message from 'mailer-daemon@googlemail.com' with subject 'Delivery Status Notification (Failure)'

Let's also think of how we could be catching this with a monitoring system?

[jywarren]

OK @icarito found:

E, [2019-05-07T16:15:33.517519 #1] ERROR -- : undefined method `body' for nil:NilClass                                                                         
/app/app/models/comment.rb:265:in `add_comment'
/app/app/models/comment.rb:218:in `receive_mail' 

[jywarren]

This line:

plots2/app/models/comment.rb

Line 265 in 07490f2

mail_doc = Nokogiri::HTML(mail.html_part.body.decoded) # To parse the mail to extract comment content and reply content

[jywarren]

OK! I got a very complete log out:

Key section:

E, [2019-04-30T22:59:40.881920 #1] ERROR -- : MySQL client is not connected
/usr/local/bundle/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/mysql2_adapter.rb:82:in `escape'
/usr/local/bundle/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/mysql2_adapter.rb:82:in `quote_string'
/usr/local/bundle/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/quoting.rb:167:in `_quote'
/usr/local/bundle/gems/activerecord-

AND

/app/app/models/comment.rb:209: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'

Comment.rb line 209:

plots2/app/models/comment.rb

Line 209 in 07490f2

user = User.where(email: mail.from.first).first

[jywarren]

And noting - this is intermittent! This comment went through 2 days ago: https://publiclab.org/notes/warren/05-06-2019/a-big-welcome-to-our-outreachy-gsoc-team-for-2019#c24034

[jywarren]

I think this MySQL client is not connected error is the issue; i scanned the entire log and got:

cat log/mailman.log | grep MySQL
E, [2019-04-22T15:07:10.098763 #1] ERROR -- : Mysql2::Error::ConnectionError: MySQL server has gone away: SELECT  `rusers`.* FROM `rusers` WHERE `rusers`.`email` = 'notifications@publiclab.org' ORDER BY `rusers`.`id` ASC LIMIT 1
E, [2019-04-22T15:44:18.431453 #1] ERROR -- : MySQL client is not connected
E, [2019-04-22T15:44:18.742357 #1] ERROR -- : MySQL client is not connected
E, [2019-04-22T15:44:19.147765 #1] ERROR -- : MySQL client is not connected
E, [2019-04-22T15:44:25.142201 #1] ERROR -- : MySQL client is not connected
E, [2019-04-22T15:44:25.435404 #1] ERROR -- : MySQL client is not connected
<p><strong>DBMS</strong> MySQL</p>
E, [2019-04-22T16:08:04.618267 #1] ERROR -- : MySQL client is not connected
E, [2019-04-22T16:08:27.683279 #1] ERROR -- : MySQL client is not connected
E, [2019-04-22T17:19:53.173945 #1] ERROR -- : MySQL client is not connected
E, [2019-04-22T17:20:00.529352 #1] ERROR -- : MySQL client is not connected
E, [2019-04-22T17:20:01.152438 #1] ERROR -- : MySQL client is not connected
E, [2019-04-22T17:20:02.300158 #1] ERROR -- : MySQL client is not connected
E, [2019-04-22T17:20:03.693919 #1] ERROR -- : MySQL client is not connected
E, [2019-04-22T17:20:11.236015 #1] ERROR -- : MySQL client is not connected
E, [2019-04-25T16:23:24.692530 #1] ERROR -- : Mysql2::Error::ConnectionError: MySQL server has gone away: SELECT  `rusers`.* FROM `rusers` WHERE `rusers`.`email` = 'notifications@publiclab.org' ORDER BY `rusers`.`id` ASC LIMIT 1
E, [2019-04-25T16:24:19.140844 #1] ERROR -- : MySQL client is not connected
E, [2019-04-25T16:26:56.881658 #1] ERROR -- : MySQL client is not connected
E, [2019-04-25T16:27:13.447619 #1] ERROR -- : MySQL client is not connected
E, [2019-04-26T13:05:56.291136 #1] ERROR -- : MySQL client is not connected
E, [2019-04-26T13:06:23.716742 #1] ERROR -- : MySQL client is not connected
E, [2019-04-26T19:31:28.518442 #1] ERROR -- : MySQL client is not connected
E, [2019-04-26T19:31:55.678300 #1] ERROR -- : MySQL client is not connected
E, [2019-04-26T19:35:30.448745 #1] ERROR -- : MySQL client is not connected
E, [2019-04-29T16:04:18.888379 #1] ERROR -- : MySQL client is not connected
<p><strong>DBMS</strong> MySQL</p>
E, [2019-04-29T18:21:25.562762 #1] ERROR -- : MySQL client is not connected
<p><strong>DBMS</strong> MySQL</p>
E, [2019-04-29T18:22:29.829764 #1] ERROR -- : MySQL client is not connected
<p><strong>DBMS</strong> MySQL</p>
E, [2019-04-29T18:22:57.121792 #1] ERROR -- : MySQL client is not connected
E, [2019-04-29T18:40:37.640637 #1] ERROR -- : MySQL client is not connected
E, [2019-04-29T20:11:33.063534 #1] ERROR -- : MySQL client is not connected
E, [2019-04-29T20:51:03.141527 #1] ERROR -- : MySQL client is not connected
rkbench/">MySQL Workbench</a>. I didn't use it because (as far as I can t=
E, [2019-04-29T21:16:09.328757 #1] ERROR -- : MySQL client is not connected
rkbench/">MySQL Workbench</a>. I didn't use it because (as far as I can t=
E, [2019-04-29T21:19:53.525783 #1] ERROR -- : MySQL client is not connected
rkbench/">MySQL Workbench</a>. I didn't use it because (as far as I can t=
E, [2019-04-29T21:20:04.532678 #1] ERROR -- : MySQL client is not connected
E, [2019-04-30T03:44:13.782513 #1] ERROR -- : MySQL client is not connected
E, [2019-04-30T13:42:44.643238 #1] ERROR -- : MySQL client is not connected
E, [2019-04-30T13:49:21.435741 #1] ERROR -- : MySQL client is not connected
E, [2019-04-30T14:27:19.279732 #1] ERROR -- : MySQL client is not connected
E, [2019-04-30T17:19:06.142565 #1] ERROR -- : MySQL client is not connected
E, [2019-04-30T22:59:40.881920 #1] ERROR -- : MySQL client is not connected

[icarito]

Here's all errors for the last week:

E, [2019-04-30T03:44:13.782137 #1] ERROR -- : Exception occurred while receiving message:
E, [2019-04-30T03:44:13.782513 #1] ERROR -- : MySQL client is not connected
E, [2019-04-30T13:42:44.622083 #1] ERROR -- : Exception occurred while receiving message:
E, [2019-04-30T13:42:44.643238 #1] ERROR -- : MySQL client is not connected
E, [2019-04-30T13:49:21.408575 #1] ERROR -- : Exception occurred while receiving message:
E, [2019-04-30T13:49:21.435741 #1] ERROR -- : MySQL client is not connected
E, [2019-04-30T14:27:19.279368 #1] ERROR -- : Exception occurred while receiving message:
ECqQYv0VXj+lQDY+nV+oyOlKD2LjNhLvSJLY9p1EiElEfv6M5OhGNjdJ7ulj
Et3iefdUAwHqUkEnTcE/v/jO9/o21p+3/6FkFKKzMR50qQLin8maAai+sSlN
EibiKUBDgNAQIDQECC2C9n8BBgBAP0FWplWQxQAAAABJRU5ErkJggg==
E, [2019-04-30T14:27:19.279732 #1] ERROR -- : MySQL client is not connected
E, [2019-04-30T17:19:06.142194 #1] ERROR -- : Exception occurred while receiving message:
E, [2019-04-30T17:19:06.142565 #1] ERROR -- : MySQL client is not connected
E, [2019-04-30T22:59:40.871795 #1] ERROR -- : Exception occurred while receiving message:
E, [2019-04-30T22:59:40.881920 #1] ERROR -- : MySQL client is not connected
E, [2019-05-03T13:47:46.083228 #1] ERROR -- : Exception occurred while receiving message:
E, [2019-05-03T13:47:46.085568 #1] ERROR -- : undefined method `body' for nil:NilClass
E, [2019-05-07T16:15:33.502168 #1] ERROR -- : Exception occurred while receiving message:
E, [2019-05-07T16:15:33.517519 #1] ERROR -- : undefined method `body' for nil:NilClass

Most of the errors would have to have happened last week but not this one.
How can I reproduce?

Another thing, we are using a gmail mailbox? Could some of the email be trapped in SPAM folder?
Or worse: https://www.tablix.org/~avian/blog/archives/2019/04/google_is_eating_our_mail/

[icarito]

I just tried replying to a notification and the comment went thru:
https://publiclab.org/notes/warren/05-07-2019/introducing-a-draft-style-guide-for-public-lab?_=1557376882#