Mandrill webhook fails with connect() timeout

[m4olivei]

Been getting these emails periodically from Madrill with this error:

Your Mandrill webhook at URL https://www.mydomain.ca/en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a has failed with the following error: POST to https://www.broadbentinstitute.ca/en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a failed: connect() timed out!.

Has anyone else been getting these, does anyone know what causes them or what can be done to fix it?

Using:
Drupal 7.25
CiviCRM 4.3.5
Mandrill Transactional Emails v1.2

Thanks,
Matt

[pradpnayak]

I tried hitting those URLs from the browser and also tried requesting them via cURL. They seem to be working fine without returning a timeout error. Could you please check your access logs for any other errors?

[m4olivei]

Yeah, I found the same thing. Checking my Apache access logs, most of the entries are empty responses with status code 200, eg.

54.214.172.100 - - [17/Dec/2013:13:31:46 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 200 - "-" "Mandrill-Webhook/1.0"
54.214.90.95 - - [17/Dec/2013:13:31:58 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 200 - "-" "Mandrill-Webhook/1.0"

There are a couple that are a response code of 200, but return non-empty responses, like this:

54.214.68.124 - - [17/Dec/2013:13:33:49 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 200 1486 "-" "Mandrill-Webhook/1.0"

Then there are a couple 500 errors that are mixed in as well. Comparing to the connect timeout errors logged in Mandrill, they match up, so it seems these are the requests that are trigging the mandrill errors:

50.112.20.93 - - [10/Dec/2013:22:50:00 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 500 3897 "-" "Mandrill-Webhook/1.0"
54.244.150.44 - - [11/Dec/2013:00:30:02 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 500 3897 "-" "Mandrill-Webhook/1.0"
50.112.36.105 - - [11/Dec/2013:06:15:00 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 500 3897 "-" "Mandrill-Webhook/1.0"
54.244.151.124 - - [11/Dec/2013:13:46:46 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 500 - "-" "Mandrill-Webhook/1.0"
54.245.170.97 - - [13/Dec/2013:09:55:00 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 500 3897 "-" "Mandrill-Webhook/1.0"
54.214.94.6 - - [13/Dec/2013:15:05:02 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 500 3897 "-" "Mandrill-Webhook/1.0"
54.218.159.163 - - [14/Dec/2013:09:35:01 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 500 3897 "-" "Mandrill-Webhook/1.0"
54.244.151.124 - - [19/Dec/2013:08:40:00 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 500 3897 "-" "Mandrill-Webhook/1.0"
50.112.36.105 - - [20/Dec/2013:11:50:01 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 500 3897 "-" "Mandrill-Webhook/1.0"
54.214.94.6 - - [21/Dec/2013:09:55:02 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 500 3897 "-" "Mandrill-Webhook/1.0"
54.214.69.176 - - [22/Dec/2013:11:50:02 -0500] "POST /en/civicrm/ajax/mte/callback?mandrillSecret=55458e1ad5e8c55a HTTP/1.1" 500 3897 "-" "Mandrill-Webhook/1.0"

Thoughts? I'm going to look through Drupal logs to see if anything comes up there.

Thanks for your help.

[JoeMurray]

It appears from your log that there are timeouts or maybe some other failure when processing a callback from Mandrill. Do you find anything interesting in your Drupal logs around these times? Do you have any useful errors from these time in your PHP logs. Much less likely, but I still want to ask: is it possible that your system was just too busy to complete its response at these times?

As you are only getting 0 to 3 of these a day, I'm not keen to suggest this, but is there some way to capture the post information on the callbacks that are failing? Is it available from Mandrill? If not, there are various methods suggested from Google for doing this, eg Apache mod_dumpio seems too dangerous for various reasons, including that you will write too much to disk and possibly bring your system down. Mod_security seems best (http://www.modsecurity.org/), since you can limit writing post data to a log to just this URL. See https://github.com/SpiderLabs/ModSecurity/wiki/Reference-Manual#wiki-ARGS_POST. HTH.

[m4olivei]

Unfortunately, my Drupal logs were full of PHP Warnings about headers already sent. Which means that the logs don't go back far enough to check against the Mandrill timeouts until the next time they occur.

Incidentally the PHP warnings my log was full of had to do with Cron not running, which was due to a rouge module causing a redirect during Cron. I've corrected that issue, so now Cron runs cleanly and those PHP Warnings don't pollute my logs anymore.

Also frustrating was that my web host recently went through a CPanel upgrade and error log storage times got cut, so I don't have those to look against either.

All that is to say, your suggestions are great and I'll continue to watch the progress of this as the logs fill with more relevant information.

Thanks for your help so far.

[JoeMurray]

Please reopen if the issue recurs.

[yosefromano]

Has anyone made progress on this issue?
I am experiencing the same problem.
Thanks

[JoeMurray]

Hi @yosefromano,
Could you provide more details on the history of your use of the extension (is it a new install or it was working for ages and this just started happening...) as well as your cms and civi and extension versions? Also, could you provide some Apache logs like above?

[yosefromano]

The extension works and has been working. Error occurred only after setting up the webhook to let civicrm know about bounces, opens... I sent a test email to 3 addresses, 1 of which was a fake in order to test the bounce. I have since been receiving 6 emails a day to notify me of the bounce. I also noticed that error in the webshook setting section in mandrill.

I have civicrm 4.6.5 running on Drupal 7.38 .

mandrill posts this error under the webhook : Error: POST to https://www.msite.org/civicrm/ajax/mte/callback?mandrillSecret=*********989c failed with 500:

Drupal posts :Notice: Undefined index: event in CRM_Mte_BAO_Mandrill::processMandrillCalls() (line 84 of /srv/bindings/.../code/sites/all/extensions/biz.jmaconsulting.mte-2.0/CRM/Mte/BAO/Mandrill.php).

Thanks!

[pradpnayak]

Can you please update the extension and check if still get error

Here is the download link:
https://github.com/JMAConsulting/biz.jmaconsulting.mte/archive/v2.1.beta.zip