Inbound email not working

elsaadj · 30 April 2018 02:02

I can’t get the inbound email to work, checked the inbound email works and configured correctly in suitecrm, the cron is running, scheduler is active to check inbound, no errors in php error.log, no errors in suitercrm.log.

Noticed no logs when you click on a schedules for any of them (last run : Never), not sure if they should log each run to not, but they seem to be running at least workflow since it sends emails on case updates.

using latest release 7.10.4

reply test email subject: Re: [CASE:79] Support

suitecrm_developer · 30 April 2018 05:49

Hi,
If there is no Job Running logs in the Scheduled Job detail view page, then the CRON job is not working properly.
Please check the CRON, is it properly setup on your server. And also enable automatic syncing of new emails in the Email settings.

Thanks

pgr · 30 April 2018 10:48

I agree with suitecrm_developer, your cron jobs aren’t really running.

The fact that the Case Updates send emails doesn’t contradict this: Workflows start in different ways depending on their kind. If they are triggered by records saved (as in the Case updates), the scheduler isn’t involved.

elsaadj · 30 April 2018 12:37

$ crontab -l

- - - - www-data /usr/bin/php -c /etc/php/7.0/apache2/php.ini -f /var/www/suitecrm/cron.php > /dev/null 2>&1

grep cron /var/log/syslog

Apr 30 12:27:01 ubuntu CRON[11030]: (www-data) CMD (www-data /usr/bin/php -c /etc/php/7.0/apache2/php.ini -f /var/www/suitecrm/cron.php > /dev/null 2>&1)
Apr 30 12:27:01 ubuntu CRON[11031]: (jme) CMD (www-data /usr/bin/php -c /etc/php/7.0/apache2/php.ini -f /var/www/suitecrm/cron.php > /dev/null 2>&1)
Apr 30 12:28:01 ubuntu CRON[11034]: (www-data) CMD (www-data /usr/bin/php -c /etc/php/7.0/apache2/php.ini -f /var/www/suitecrm/cron.php > /dev/null 2>&1)
Apr 30 12:28:01 ubuntu CRON[11035]: (jme) CMD (www-data /usr/bin/php -c /etc/php/7.0/apache2/php.ini -f /var/www/suitecrm/cron.php > /dev/null 2>&1)

Cron is running. How to check if suitecrm/cron.php is being executed?

System:
$ mysql --version
mysql Ver 14.14 Distrib 5.7.22, for Linux (x86_64) using EditLine wrapper
$ php -v
PHP 7.0.28-0ubuntu0.16.04.1 (cli) ( NTS )
Copyright © 1997-2017 The PHP Group
Zend Engine v3.0.0, Copyright © 1998-2017 Zend Technologies
with Zend OPcache v7.0.28-0ubuntu0.16.04.1, Copyright © 1999-2017, by Zend Technologies

$ apache2 -v
Server version: Apache/2.4.18 (Ubuntu)
Server built: 2018-04-18T14:53:04

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 16.04 LTS
Release: 16.04
Codename: xenial

pgr · 30 April 2018 17:06

Do you have two crontabs running?

Check with commands asking for the specific user’s crontab, like


crontab -l -u root
crontab -l -u www-data
crontab -l -u jme

It looks like your using yet another crontab which is the “system-wide crontab”, where an additional column is used to specify user name. This avoids using one crontab per user. It’s ok to keep using it, just make sure there are no other crontabs doing the same thing.

If you find one, fix it, but then also fix permissions for your entire installation (you should only have to do this once after removing crontabs from different users).

If your log level is DEBUG you will see messages regarding cron.php in suitecrm.log.

elsaadj · 30 April 2018 19:04

Removed the duplicate cron that was doing the same thing. Turned on DEBUG and debug messages coming out every minute but can’t tell if it is result of cron. The schedules still show last run never though.

$ tail -f /var/log/syslog
Apr 30 18:45:01 ubuntu CRON[14767]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Apr 30 18:45:01 ubuntu CRON[14768]: (www-data) CMD (www-data /usr/bin/php -c /etc/php/7.0/apache2/php.ini -f /var/www/su

$ tail -f suitecrm.log
Mon Apr 30 13:09:51 2018 [11990][-none-][DEBUG] current_language is: en_us
Mon Apr 30 13:09:51 2018 [11990][-none-][DEBUG] Found cache backend SugarCacheMemory
Mon Apr 30 13:09:51 2018 [11990][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Mon Apr 30 13:09:51 2018 [11990][-none-][DEBUG] Found cache backend SugarCacheZend
Mon Apr 30 13:09:51 2018 [11990][-none-][DEBUG] Found cache backend SugarCacheRedis
Mon Apr 30 13:09:51 2018 [11990][-none-][DEBUG] Found cache backend SugarCachesMash
Mon Apr 30 13:09:51 2018 [11990][-none-][DEBUG] Found cache backend SugarCacheWincache
Mon Apr 30 13:09:51 2018 [11990][-none-][DEBUG] Found cache backend SugarCacheMemcache
Mon Apr 30 13:09:51 2018 [11990][-none-][DEBUG] Found cache backend SugarCacheMemcached
Mon Apr 30 13:09:51 2018 [11990][-none-][DEBUG] Found cache backend SugarCacheFile
Mon Apr 30 13:09:51 2018 [11990][-none-][DEBUG] Found cache backend SugarCacheAPC
Mon Apr 30 13:09:51 2018 [11990][-none-][INFO] Found language file: en_us.lang.php
Mon Apr 30 13:09:51 2018 [11990][-none-][INFO] Found custom language file: en_us.lang.php
Mon Apr 30 13:09:51 2018 [11990][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = ‘Active’ and deleted = 0
Mon Apr 30 13:09:51 2018 [11990][-none-][INFO] Query Execution Time:0.00038385391235352
Mon Apr 30 13:09:51 2018 [11990][-none-][INFO] Query:SELECT category, name, value FROM config
Mon Apr 30 13:09:51 2018 [11990][-none-][INFO] Query Execution Time:0.00034809112548828
Mon Apr 30 13:09:51 2018 [11990][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = ‘system’
Mon Apr 30 13:09:51 2018 [11990][-none-][INFO] Query Execution Time:0.00019598007202148
Mon Apr 30 13:09:51 2018 [11990][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = ‘68adf809-54af-42a7-a02d-5974d159fb15’
Mon Apr 30 13:09:51 2018 [11990][-none-][INFO] Query Execution Time:0.00025796890258789
Mon Apr 30 13:09:52 2018 [11990][-none-][DEBUG] Hook called: ::after_entry_point
Mon Apr 30 13:09:52 2018 [11990][-none-][DEBUG] Including module specific hook file for custom/modules
Mon Apr 30 13:09:52 2018 [11990][-none-][DEBUG] Including Ext hook file for custom/application
Mon Apr 30 13:09:52 2018 [11990][-none-][DEBUG] Hook called: ::after_session_start
Mon Apr 30 13:09:52 2018 [11990][-none-][DEBUG] Unable to find SugarController:: get
Mon Apr 30 13:09:52 2018 [11990][-none-][DEBUG] We have an authenticated user id: 5f866ce7-1b02-0489-040b-5978c66ca7d6
Mon Apr 30 13:09:52 2018 [11990][-none-][DEBUG] Hook called: Users::before_retrieve
Mon Apr 30 13:09:52 2018 [11990][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Mon Apr 30 13:09:52 2018 [11990][-none-][DEBUG] Retrieve User : SELECT users.* FROM users WHERE users.id = ‘5f866ce7-1b02-0489-040b-5978c66ca7d6’ AND users.deleted=0
Mon Apr 30 13:09:52 2018 [11990][-none-][DEBUG] Limit Query:SELECT users.* FROM users WHERE users.id = ‘5f866ce7-1b02-0489-040b-5978c66ca7d6’ AND users.deleted=0 Start: 0 count: 1
Mon Apr 30 13:09:52 2018 [11990][-none-][INFO] Query:SELECT users.* FROM users WHERE users.id = ‘5f866ce7-1b02-0489-040b-5978c66ca7d6’ AND users.deleted=0 LIMIT 0,1
Mon Apr 30 13:09:52 2018 [11990][-none-][INFO] Query Execution Time:0.0005791187286377
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] get_user_array query: SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][INFO] Query Execution Time:0.0003349781036377
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][INFO] Query:SELECT u1.first_name, u1.last_name from users u1, users u2 where u1.id = u2.reports_to_id AND u2.id = ‘5f866ce7-1b02-0489-040b-5978c66ca7d6’ and u1.deleted=0
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][INFO] Query Execution Time:0.00023102760314941
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][INFO] Query:SELECT
ea.email_address,
ea.email_address_caps,
ea.invalid_email,
ea.opt_out,
ea.confirm_opt_in,
ea.date_created,
ea.date_modified,
ear.id,
ear.email_address_id,
ear.bean_id,
ear.bean_module,
ear.primary_address,
ear.reply_to_address,
ear.deleted
FROM email_addresses ea LEFT JOIN email_addr_bean_rel ear ON ea.id = ear.email_address_id
WHERE
ear.bean_module = ‘Users’
AND ear.bean_id = ‘5f866ce7-1b02-0489-040b-5978c66ca7d6’
AND ear.deleted = 0
ORDER BY ear.reply_to_address, ear.primary_address DESC
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][INFO] Query Execution Time:0.0004429817199707
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] Hook called: Users::after_retrieve
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] FACTOR AUTH: User does`nt need factor auth
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] Current user is: jamal
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] Current user is: jamal
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] setting cookie ck_login_id_20 to 5f866ce7-1b02-0489-040b-5978c66ca7d6
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] setting cookie ck_login_language_20 to en_us
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] current_language is: en_us
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][INFO] Found language file: en_us.lang.php
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][INFO] Found custom language file: en_us.lang.php
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] Performing action: action_get MODULE: Alerts
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] get_full_list: order_by = ‘alerts.date_entered’ and where = ‘alerts.assigned_user_id = ‘5f866ce7-1b02-0489-040b-5978c66ca7d6’ AND is_read != ‘1’’
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (modified_user_link).
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (created_by_link).
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (assigned_user_link).
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] process_order_by: (alerts.date_entered) does not have a vardef entry.
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] process_full_list_query: query is SELECT alerts.* , jt0.user_name modified_by_name , jt0.created_by modified_by_name_owner , ‘Users’ modified_by_name_mod , jt1.user_name created_by_name , jt1.created_by created_by_name_owner , ‘Users’ created_by_name_mod , jt2.user_name assigned_user_name , jt2.created_by assigned_user_name_owner , ‘Users’ assigned_user_name_mod FROM alerts LEFT JOIN users jt0 ON alerts.modified_user_id=jt0.id AND jt0.deleted=0

AND jt0.deleted=0 LEFT JOIN users jt1 ON alerts.created_by=jt1.id AND jt1.deleted=0

AND jt1.deleted=0 LEFT JOIN users jt2 ON alerts.assigned_user_id=jt2.id AND jt2.deleted=0

AND jt2.deleted=0 where (alerts.assigned_user_id = ‘5f866ce7-1b02-0489-040b-5978c66ca7d6’ AND is_read != ‘1’) AND alerts.deleted=0
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][INFO] Query: SELECT alerts.* , jt0.user_name modified_by_name , jt0.created_by modified_by_name_owner , ‘Users’ modified_by_name_mod , jt1.user_name created_by_name , jt1.created_by created_by_name_owner , ‘Users’ created_by_name_mod , jt2.user_name assigned_user_name , jt2.created_by assigned_user_name_owner , ‘Users’ assigned_user_name_mod FROM alerts LEFT JOIN users jt0 ON alerts.modified_user_id=jt0.id AND jt0.deleted=0

AND jt0.deleted=0 LEFT JOIN users jt1 ON alerts.created_by=jt1.id AND jt1.deleted=0

AND jt1.deleted=0 LEFT JOIN users jt2 ON alerts.assigned_user_id=jt2.id AND jt2.deleted=0

AND jt2.deleted=0 where (alerts.assigned_user_id = ‘5f866ce7-1b02-0489-040b-5978c66ca7d6’ AND is_read != ‘1’) AND alerts.deleted=0
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][INFO] Query Execution Time:0.00061392784118652
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] process_full_list_query: result is mysqli_result Object
(
[current_field] => 0
[field_count] => 22
[lengths] =>
[num_rows] => 0
[type] => 0
)

Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] Hook called: ::server_round_trip
Mon Apr 30 13:09:52 2018 [11990][5f866ce7-1b02-0489-040b-5978c66ca7d6][DEBUG] Calling MySQLi::disconnect()

elsaadj · 30 April 2018 19:58

Also checked the permissions for the entire installation, all owned by www-data www-data

pgr · 1 May 2018 11:37

You have to do your own work sorting out the logs. Look for FATAL or ERROR messages. Grep them for “cron” or for “job”.

And pay attention to the timestamps, make sure you’re looking at the logs coming from the Schedulers. The ones you pasted don’t look like they are Scheduler jobs, they look like a screen being rendered, and a logic hook, and they cover two seconds. Try to choose a time where the system is inactive, nobody’s using it (or force this by disconnecting the network for a minute…) wait for the Jobs to kick in, and get that.

elsaadj · 2 May 2018 00:57

Figured it out, the cron command had * * * * instead of * * * * *.
Scheduler is now running and case history shows unread messages.
Now, why the case email message content not getting added to case update?

jobname:Check Inbound Mailboxes
job:function::pollMonitoredInboxesAOP

pgr · 2 May 2018 11:19

I don’t know, but you can start by checking your settings and reading some more about group emails and email settings:

https://docs.suitecrm.com/user/modules/email-settings/#_create_case_from_email

elsaadj · 4 May 2018 15:46

I did check mail settings and read about email group, but no info found about how to make inbound emails update a case. Found config check to make inbound email create new case but that is all.

Can suitecrm inbound email update case or just put the email in the case unread list?

pgr · 4 May 2018 16:15

In Admin / Inbound Email settings, All Accounts, have you checked your settings for the CASE recognition?

Do your reply emails still contain that string?

elsaadj · 4 May 2018 16:42

Yes, Case Macro: [CASE:%1] and reply email subject contains Re:[CASE:79]

It is associating the email to the case correctly as it puts the email in the case history as unread email, but it doesn’t add the content of the email to the case update.

elsaadj · 4 May 2018 17:00

https://pasteboard.co/HjE2EhY.png

https://pasteboard.co/HjE32PY.png

pgr · 4 May 2018 17:17

What do you mean by “does not add the content to the case update”?

If you mean the Updates threaded section, I think that’s a separate way of handling cases, it doesn’t connect with email. But I’m not sure. Have you ever seen email content there?

elsaadj · 4 May 2018 17:33

No, but I am under the impression from what I read is that when inbound email is received, suitecrm will associate the email with a case using macro [CASE:%1] and put the email body content in case update. So, your updates and who ever replying with email updates will be in case thread.

I can see the email body content in the case history list if I click on it and open it, but it doesn’t put the reply email body content in the case update thread.

So I am not sure if suitecrm suppose to do that as part of the inbound email settings or need other trigger like workflow.

pgr · 4 May 2018 21:26

I’m not sure the area “Case Updates Threaded” is connected to inbound email.

This post seems to think it is
https://suitecrm.com/suitecrm/forum/suitecrm-7-0-discussion/16572-advice-on-email-best-practice-to-use-shared-email-account#55827