AnsweredAssumed Answered

Slow Email response with Gmail and errors: Exception Occurred Communication Error

Question asked by Marc Hertz on Aug 28, 2014
Sugar Version 6.5.16 (Build 1082)
Community Edition
Category Email
Operating System Linux 2.6.18 Red Hat Enterprise Linux ES release 4 (Nahant Update 4)
PHP Version 5.2.17
Database MySQL client version: 5.1.45
Web Server Apache/2.0.64

STEPS TO REPRODUCE

  1. Select Email Module
  2. Select Inbox for Group or Individual GMail account Email.
  3. Select single emails
  4. "Loading Message" in preview pane displays; takes 25+ seconds for message to display in preview window
  5. Double click single message.  New message window opens but it takes 25+ seconds for message to fill window.
  6. Select Delete "Deleting message one moment" processing message displays for 25+ seconds before deleting
  7. Select multiple message Deleting message one moment" processing message displays for 25+ PER MESSAGE  before deleting
  8. Select any other menu item or module in sugar before item deletes generates errors: Exception Occurred Communication Error

TROUBLESHOOTING STEPS

  • Review log files for errors; set Slow query time threshold (msec): 50  and reviewed log files
  • Checked apache error log
  • Repair and Rebuild
  • Repaired and Optimized tables in database
  • Made all schedulers inactive
  • Made sure all Mail accounts were not set to import emails automatically; and not set to create case from email
  • Made all gmail imap email accounts inactive; tested with pop3 and different gmail account
Here is the Log after testing with a new gmail account:

Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] current_language is: en_us
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Found cache backend SugarCacheAPC
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Found cache backend SugarCachesMash
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Found cache backend SugarCacheRedis
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Found cache backend SugarCacheZend
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Found cache backend SugarCacheFile
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Found cache backend SugarCacheWincache
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Found cache backend SugarCacheMemory
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Found cache backend SugarCacheMemcache
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Found cache backend SugarCacheMemcached
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Found language file: en_us.lang.php
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Found extended language file: en_us.lang.ext.php
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Found custom language file: en_us.lang.php
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Query Execution Time:0.00018405914306641
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Query:SELECT category, name, value FROM config
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Query Execution Time:0.00028419494628906
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system'
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Query Execution Time:9.8943710327148E-5
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '9251bc15-208e-8c28-1f0f-4e0a11f5606a'
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Query Execution Time:0.00013995170593262
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Hook called: ::after_entry_point
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Including Ext hook file for custom/application
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Found language file: en_us.lang.php
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Found extended language file: en_us.lang.ext.php
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Found custom language file: en_us.lang.php
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Hook called: Users::before_retrieve
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Retrieve User : SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0
Thu Aug 28 13:54:01 2014 [11972][-none-][DEBUG] Limit Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 Start: 0 count: 1
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 LIMIT 0,1
Thu Aug 28 13:54:01 2014 [11972][-none-][INFO] Query Execution Time:0.0002291202545166
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] Loading Preferences DB admin
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query:SELECT contents FROM user_preferences WHERE assigned_user_id='1' AND category = 'global' AND deleted = 0
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query Execution Time:0.0002140998840332
Thu Aug 28 13:54:01 2014 [11972][1][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
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query:SELECT id, first_name, last_name, user_name from users WHERE 1=1 ORDER BY first_name, last_name ASC
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query Execution Time:0.0002739429473877
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query:SELECT u1.first_name, u1.last_name from users  u1, users  u2 where u1.id = u2.reports_to_id AND u2.id = '1' and u1.deleted=0
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query Execution Time:0.00013113021850586
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query:SELECT ea.email_address, ea.email_address_caps, ea.invalid_email, ea.opt_out, 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 = '1'
                AND ear.deleted = 0
                ORDER BY ear.reply_to_address, ear.primary_address DESC
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query Execution Time:0.00032997131347656
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] Hook called: Users::after_retrieve
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] --------------------------------------------> at cron.php <--------------------------------------------
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] Using SugarCronJobs as CRON driver
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query:SELECT id FROM job_queue WHERE status='running' AND date_modified <= '2014-08-27 19:54:01'
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query Execution Time:0.00073814392089844
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] get_full_list:  order_by = '' and where = 'schedulers.status='Active' AND NOT EXISTS(SELECT id FROM job_queue WHERE scheduler_id=schedulers.id AND status!='done')'
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] SugarBean[Scheduler].load_relationships, Loading relationship (created_by_link).
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] SugarBean[Scheduler].load_relationships, Loading relationship (modified_user_link).
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] process_full_list_query: query is  SELECT  schedulers.*  , LTRIM(RTRIM(CONCAT(IFNULL(jt0.first_name,''),' ',IFNULL(jt0.last_name,'')))) created_by_name , jt0.created_by created_by_name_owner  , 'Users' created_by_name_mod , LTRIM(RTRIM(CONCAT(IFNULL(jt1.first_name,''),' ',IFNULL(jt1.last_name,'')))) modified_by_name , jt1.created_by modified_by_name_owner  , 'Users' modified_by_name_mod FROM schedulers   LEFT JOIN  users jt0 ON jt0.id=schedulers.created_by AND jt0.deleted=0
 AND jt0.deleted=0  LEFT JOIN  users jt1 ON schedulers.modified_user_id=jt1.id AND jt1.deleted=0

 AND jt1.deleted=0 where (schedulers.status='Active' AND NOT EXISTS(SELECT id FROM job_queue WHERE scheduler_id=schedulers.id AND status!='done')) AND schedulers.deleted=0
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query: SELECT  schedulers.*  , LTRIM(RTRIM(CONCAT(IFNULL(jt0.first_name,''),' ',IFNULL(jt0.last_name,'')))) created_by_name , jt0.created_by created_by_name_owner  , 'Users' created_by_name_mod , LTRIM(RTRIM(CONCAT(IFNULL(jt1.first_name,''),' ',IFNULL(jt1.last_name,'')))) modified_by_name , jt1.created_by modified_by_name_owner  , 'Users' modified_by_name_mod FROM schedulers   LEFT JOIN  users jt0 ON jt0.id=schedulers.created_by AND jt0.deleted=0
 AND jt0.deleted=0  LEFT JOIN  users jt1 ON schedulers.modified_user_id=jt1.id AND jt1.deleted=0

 AND jt1.deleted=0 where (schedulers.status='Active' AND NOT EXISTS(SELECT id FROM job_queue WHERE scheduler_id=schedulers.id AND status!='done')) AND schedulers.deleted=0
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query Execution Time:0.00029206275939941
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] process_full_list_query: result is mysqli_result Object
(
)

Thu Aug 28 13:54:01 2014 [11972][1][INFO] -----> Scheduler found [ 0 ] ACTIVE jobs
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] ----->No Schedulers found
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Get One: |SELECT id FROM job_queue WHERE execute_time <= '2014-08-28 19:54:01' AND status = 'queued' ORDER BY date_entered ASC|
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] Limit Query:SELECT id FROM job_queue WHERE execute_time <= '2014-08-28 19:54:01' AND status = 'queued' ORDER BY date_entered ASC Start: 0 count: 1
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query:SELECT id FROM job_queue WHERE execute_time <= '2014-08-28 19:54:01' AND status = 'queued' ORDER BY date_entered ASC LIMIT 0,1
Thu Aug 28 13:54:01 2014 [11972][1][INFO] Query Execution Time:0.00069808959960938
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] Hook called: ::server_round_trip
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] Calling MySQLi::disconnect()
Thu Aug 28 13:54:01 2014 [11972][1][DEBUG] Calling MySQLi::disconnect()
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] current_language is: en_us
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Found cache backend SugarCacheAPC
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Found cache backend SugarCachesMash
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Found cache backend SugarCacheRedis
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Found cache backend SugarCacheZend
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Found cache backend SugarCacheFile
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Found cache backend SugarCacheWincache
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Found cache backend SugarCacheMemory
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Found cache backend SugarCacheMemcache
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Found cache backend SugarCacheMemcached
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Found language file: en_us.lang.php
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Found extended language file: en_us.lang.ext.php
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Found custom language file: en_us.lang.php
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Query Execution Time:0.00017809867858887
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Query:SELECT category, name, value FROM config
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Query Execution Time:0.00029277801513672
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system'
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Query Execution Time:9.608268737793E-5
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '9251bc15-208e-8c28-1f0f-4e0a11f5606a'
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Query Execution Time:0.00013613700866699
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Hook called: ::after_entry_point
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Including Ext hook file for custom/application
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Found language file: en_us.lang.php
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Found extended language file: en_us.lang.ext.php
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Found custom language file: en_us.lang.php
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Hook called: Users::before_retrieve
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Retrieve User : SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0
Thu Aug 28 13:55:02 2014 [12169][-none-][DEBUG] Limit Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 Start: 0 count: 1
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 LIMIT 0,1
Thu Aug 28 13:55:02 2014 [12169][-none-][INFO] Query Execution Time:0.00020408630371094
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] Loading Preferences DB admin
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query:SELECT contents FROM user_preferences WHERE assigned_user_id='1' AND category = 'global' AND deleted = 0
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query Execution Time:0.00021100044250488
Thu Aug 28 13:55:02 2014 [12169][1][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
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query:SELECT id, first_name, last_name, user_name from users WHERE 1=1 ORDER BY first_name, last_name ASC
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query Execution Time:0.00027084350585938
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query:SELECT u1.first_name, u1.last_name from users  u1, users  u2 where u1.id = u2.reports_to_id AND u2.id = '1' and u1.deleted=0
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query Execution Time:0.00012779235839844
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query:SELECT ea.email_address, ea.email_address_caps, ea.invalid_email, ea.opt_out, 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 = '1'
                AND ear.deleted = 0
                ORDER BY ear.reply_to_address, ear.primary_address DESC
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query Execution Time:0.00026798248291016
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] Hook called: Users::after_retrieve
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] --------------------------------------------> at cron.php <--------------------------------------------
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] Using SugarCronJobs as CRON driver
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query:SELECT id FROM job_queue WHERE status='running' AND date_modified <= '2014-08-27 19:55:02'
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query Execution Time:0.00072693824768066
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] get_full_list:  order_by = '' and where = 'schedulers.status='Active' AND NOT EXISTS(SELECT id FROM job_queue WHERE scheduler_id=schedulers.id AND status!='done')'
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] SugarBean[Scheduler].load_relationships, Loading relationship (created_by_link).
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] SugarBean[Scheduler].load_relationships, Loading relationship (modified_user_link).
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] process_full_list_query: query is  SELECT  schedulers.*  , LTRIM(RTRIM(CONCAT(IFNULL(jt0.first_name,''),' ',IFNULL(jt0.last_name,'')))) created_by_name , jt0.created_by created_by_name_owner  , 'Users' created_by_name_mod , LTRIM(RTRIM(CONCAT(IFNULL(jt1.first_name,''),' ',IFNULL(jt1.last_name,'')))) modified_by_name , jt1.created_by modified_by_name_owner  , 'Users' modified_by_name_mod FROM schedulers   LEFT JOIN  users jt0 ON jt0.id=schedulers.created_by AND jt0.deleted=0
 AND jt0.deleted=0  LEFT JOIN  users jt1 ON schedulers.modified_user_id=jt1.id AND jt1.deleted=0

 AND jt1.deleted=0 where (schedulers.status='Active' AND NOT EXISTS(SELECT id FROM job_queue WHERE scheduler_id=schedulers.id AND status!='done')) AND schedulers.deleted=0
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query: SELECT  schedulers.*  , LTRIM(RTRIM(CONCAT(IFNULL(jt0.first_name,''),' ',IFNULL(jt0.last_name,'')))) created_by_name , jt0.created_by created_by_name_owner  , 'Users' created_by_name_mod , LTRIM(RTRIM(CONCAT(IFNULL(jt1.first_name,''),' ',IFNULL(jt1.last_name,'')))) modified_by_name , jt1.created_by modified_by_name_owner  , 'Users' modified_by_name_mod FROM schedulers   LEFT JOIN  users jt0 ON jt0.id=schedulers.created_by AND jt0.deleted=0
 AND jt0.deleted=0  LEFT JOIN  users jt1 ON schedulers.modified_user_id=jt1.id AND jt1.deleted=0

 AND jt1.deleted=0 where (schedulers.status='Active' AND NOT EXISTS(SELECT id FROM job_queue WHERE scheduler_id=schedulers.id AND status!='done')) AND schedulers.deleted=0
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query Execution Time:0.00027203559875488
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] process_full_list_query: result is mysqli_result Object
(
)

Thu Aug 28 13:55:02 2014 [12169][1][INFO] -----> Scheduler found [ 0 ] ACTIVE jobs
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] ----->No Schedulers found
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Get One: |SELECT id FROM job_queue WHERE execute_time <= '2014-08-28 19:55:02' AND status = 'queued' ORDER BY date_entered ASC|
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] Limit Query:SELECT id FROM job_queue WHERE execute_time <= '2014-08-28 19:55:02' AND status = 'queued' ORDER BY date_entered ASC Start: 0 count: 1
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query:SELECT id FROM job_queue WHERE execute_time <= '2014-08-28 19:55:02' AND status = 'queued' ORDER BY date_entered ASC LIMIT 0,1
Thu Aug 28 13:55:02 2014 [12169][1][INFO] Query Execution Time:0.00069093704223633
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] Hook called: ::server_round_trip
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] Calling MySQLi::disconnect()
Thu Aug 28 13:55:02 2014 [12169][1][DEBUG] Calling MySQLi::disconnect()
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] current_language is: en_us
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Found cache backend SugarCacheAPC
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Found cache backend SugarCachesMash
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Found cache backend SugarCacheRedis
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Found cache backend SugarCacheZend
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Found cache backend SugarCacheFile
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Found cache backend SugarCacheWincache
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Found cache backend SugarCacheMemory
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Found cache backend SugarCacheMemcache
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Found cache backend SugarCacheMemcached
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Found language file: en_us.lang.php
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Found extended language file: en_us.lang.ext.php
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Found custom language file: en_us.lang.php
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Query Execution Time:0.00018405914306641
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Query:SELECT category, name, value FROM config
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Query Execution Time:0.00028300285339355
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system'
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Query Execution Time:9.918212890625E-5
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '9251bc15-208e-8c28-1f0f-4e0a11f5606a'
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Query Execution Time:0.00013899803161621
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Hook called: ::after_entry_point
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Including Ext hook file for custom/application
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Found language file: en_us.lang.php
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Found extended language file: en_us.lang.ext.php
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Found custom language file: en_us.lang.php
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Hook called: Users::before_retrieve
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Retrieve User : SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0
Thu Aug 28 13:56:01 2014 [13344][-none-][DEBUG] Limit Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 Start: 0 count: 1
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 LIMIT 0,1
Thu Aug 28 13:56:01 2014 [13344][-none-][INFO] Query Execution Time:0.00023007392883301
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] Loading Preferences DB admin
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query:SELECT contents FROM user_preferences WHERE assigned_user_id='1' AND category = 'global' AND deleted = 0
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query Execution Time:0.00022101402282715
Thu Aug 28 13:56:01 2014 [13344][1][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
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query:SELECT id, first_name, last_name, user_name from users WHERE 1=1 ORDER BY first_name, last_name ASC
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query Execution Time:0.00027704238891602
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query:SELECT u1.first_name, u1.last_name from users  u1, users  u2 where u1.id = u2.reports_to_id AND u2.id = '1' and u1.deleted=0
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query Execution Time:0.00013089179992676
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query:SELECT ea.email_address, ea.email_address_caps, ea.invalid_email, ea.opt_out, 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 = '1'
                AND ear.deleted = 0
                ORDER BY ear.reply_to_address, ear.primary_address DESC
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query Execution Time:0.00032401084899902
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] Hook called: Users::after_retrieve
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] --------------------------------------------> at cron.php <--------------------------------------------
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] Using SugarCronJobs as CRON driver
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query:SELECT id FROM job_queue WHERE status='running' AND date_modified <= '2014-08-27 19:56:01'
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query Execution Time:0.00073814392089844
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] get_full_list:  order_by = '' and where = 'schedulers.status='Active' AND NOT EXISTS(SELECT id FROM job_queue WHERE scheduler_id=schedulers.id AND status!='done')'
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] SugarBean[Scheduler].load_relationships, Loading relationship (created_by_link).
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] SugarBean[Scheduler].load_relationships, Loading relationship (modified_user_link).
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] process_full_list_query: query is  SELECT  schedulers.*  , LTRIM(RTRIM(CONCAT(IFNULL(jt0.first_name,''),' ',IFNULL(jt0.last_name,'')))) created_by_name , jt0.created_by created_by_name_owner  , 'Users' created_by_name_mod , LTRIM(RTRIM(CONCAT(IFNULL(jt1.first_name,''),' ',IFNULL(jt1.last_name,'')))) modified_by_name , jt1.created_by modified_by_name_owner  , 'Users' modified_by_name_mod FROM schedulers   LEFT JOIN  users jt0 ON jt0.id=schedulers.created_by AND jt0.deleted=0
 AND jt0.deleted=0  LEFT JOIN  users jt1 ON schedulers.modified_user_id=jt1.id AND jt1.deleted=0

 AND jt1.deleted=0 where (schedulers.status='Active' AND NOT EXISTS(SELECT id FROM job_queue WHERE scheduler_id=schedulers.id AND status!='done')) AND schedulers.deleted=0
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query: SELECT  schedulers.*  , LTRIM(RTRIM(CONCAT(IFNULL(jt0.first_name,''),' ',IFNULL(jt0.last_name,'')))) created_by_name , jt0.created_by created_by_name_owner  , 'Users' created_by_name_mod , LTRIM(RTRIM(CONCAT(IFNULL(jt1.first_name,''),' ',IFNULL(jt1.last_name,'')))) modified_by_name , jt1.created_by modified_by_name_owner  , 'Users' modified_by_name_mod FROM schedulers   LEFT JOIN  users jt0 ON jt0.id=schedulers.created_by AND jt0.deleted=0
 AND jt0.deleted=0  LEFT JOIN  users jt1 ON schedulers.modified_user_id=jt1.id AND jt1.deleted=0

 AND jt1.deleted=0 where (schedulers.status='Active' AND NOT EXISTS(SELECT id FROM job_queue WHERE scheduler_id=schedulers.id AND status!='done')) AND schedulers.deleted=0
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query Execution Time:0.00033402442932129
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] process_full_list_query: result is mysqli_result Object
(
)

Thu Aug 28 13:56:01 2014 [13344][1][INFO] -----> Scheduler found [ 0 ] ACTIVE jobs
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] ----->No Schedulers found
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Get One: |SELECT id FROM job_queue WHERE execute_time <= '2014-08-28 19:56:01' AND status = 'queued' ORDER BY date_entered ASC|
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] Limit Query:SELECT id FROM job_queue WHERE execute_time <= '2014-08-28 19:56:01' AND status = 'queued' ORDER BY date_entered ASC Start: 0 count: 1
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query:SELECT id FROM job_queue WHERE execute_time <= '2014-08-28 19:56:01' AND status = 'queued' ORDER BY date_entered ASC LIMIT 0,1
Thu Aug 28 13:56:01 2014 [13344][1][INFO] Query Execution Time:0.00069999694824219
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] Hook called: ::server_round_trip
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] Calling MySQLi::disconnect()
Thu Aug 28 13:56:01 2014 [13344][1][DEBUG] Calling MySQLi::disconnect()

Outcomes