Error logs filling up with these lines

[mookie_jam]

I have SuiteCRM 7.11.4, Sugar Version 6.5.25 (Build 344), installed. I updated it from 7.11.2 through the wizard. Since then, I have started seeing how the errorlogs get flooded with the following error messages.

Any clue what is it and how can I fix it?

Thank you

suitecrm.log

Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Thu May 30 17:30:03 2019 [47015][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder

php_errorlog

[04-Jun-2019 05:48:24 CST6CDT] PHP Deprecated:  Non-static method templateParser::parse_template_bean() should not be called statically in /server/suitecrm/modules/AOS_PDF_Templates/templateParser.php on line 44

[04-Jun-2019 05:43:25 CST6CDT] PHP Deprecated:  Non-static method templateParser::parse_template_bean() should not be called statically in /server/suitecrm/modules/AOS_PDF_Templates/templateParser.php on line 44
[04-Jun-2019 05:48:24 CST6CDT] PHP Deprecated:  Methods with the same name as their class will not be constructors in a future version of PHP; mPDF has a deprecated constructor in /server/suitecrm/modules/AOS_PDF_Templates/PDF_Lib/mpdf.php on line 66

[02-Jun-2019 15:31:02 CST6CDT] PHP Fatal error:  Uncaught Exception: Database failure. Please refer to suitecrm.log for details. in /server/suitecrm/include/utils.php:1777
Stack trace:
#0 /server/suitecrm/include/database/DBManager.php(353): sugar_die('Database failur...')
#1 /server/suitecrm/nclude/database/DBManager.php(328): DBManager->registerError(' Query Failed: ...', ' Query Failed: ...', true)
#2 /server/suitecrm/include/database/MysqliManager.php(179): DBManager->checkError(' Query Failed: ...', true)
#3 //server/suitecrm/modules/InboundEmail/InboundEmail.php(4693): MysqliManager->query('SELECT count(em...', true)
#4 /server/suitecrm/modules/InboundEmail/InboundEmail.php(5250): InboundEmail->importDupeCheck('57bd867a897018e...', Object(stdClass), 'Return-Path: <i...')
#5 /server/suitecrm/module in /server/suitecrm/include/utils.php on line 1777

Cron Job Error

First if not matching End of handle create case
First if not matching End of handle create case

PHP Fatal error:  Uncaught Zend_Search_Lucene_Exception in /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene/Storage/File/Filesystem.php:65
Stack trace:
#0 /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene/Storage/Directory/Filesystem.php(359): Zend_Search_Lucene_Storage_File_Filesystem->__construct('modules/AOD_Ind...')
#1 /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene/Index/SegmentInfo.php(286): Zend_Search_Lucene_Storage_Directory_Filesystem->getFileObject('_d.cfs')
#2 /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene.php(495): Zend_Search_Lucene_Index_SegmentInfo->__construct(Object(Zend_Search_Lucene_Storage_Directory_Filesystem), '_d', 1, -1, NULL, 1, true)
#3 /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene.php(570): Zend_Search_Lucene->_readSegmentsFile()
#4 /server/ in /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene/Storage/File/Filesystem.php on line 65

Fatal error: Uncaught Zend_Search_Lucene_Exception in /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene/Storage/File/Filesystem.php:65
Stack trace:
#0 /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene/Storage/Directory/Filesystem.php(359): Zend_Search_Lucene_Storage_File_Filesystem->__construct('modules/AOD_Ind...')
#1 /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene/Index/SegmentInfo.php(286): Zend_Search_Lucene_Storage_Directory_Filesystem->getFileObject('_d.cfs')
#2 /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene.php(495): Zend_Search_Lucene_Index_SegmentInfo->__construct(Object(Zend_Search_Lucene_Storage_Directory_Filesystem), '_d', 1, -1, NULL, 1, true)
#3 /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene.php(570): Zend_Search_Lucene->_readSegmentsFile()
#4 /server/suitecrm/modules/AOD_Index/Lib/Zend/Search/Lucene/Storage/File/Filesystem.php on line 65

[pgr]

There is probably more than one issue on those log messages…

About the ones from suitecrm.log, if you can get some more context, it would be helpful. So maybe raise log level to debug, and get a section of the log preceding those FATALs, so we can get a notion of what it was working on at the time… my guess is it’s something email related.

About the Zend Lucene errors, is that indexing scheduler job terminating correctly? You might have a corrupted index, or problems in your file permssions on the index directory. See https://pgorod.github.io/Reindex-AOD/

Never mind the “deprecated” errors.

About the “Database failure” error. I’d like to see a more complete stack trace of this one. So it usually has more than 5 levels, and then an SQL errror at the end. It would also be helpful if the values weren’t abbreviated with “…”, maybe there is some log settings to improve this? It would also be interesting to see if there is anything in suitecrm.log at that precise time.

[mookie_jam]

I have set to Debug the logger mode. Now I get this repeated many times per minute on suitecrm.log. No idea what it means…

Wed Jun  5 14:35:00 2019 [33167][1][INFO] Query Execution Time:6.103515625E-5
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] Hook called: Users::after_retrieve
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] FACTOR AUTH: User does`nt need factor auth
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] Current user is: user_master
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] Current user is: user_master
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] setting cookie ck_login_id_20 to 1
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] setting cookie ck_login_language_20 to en_us
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] current_language is: en_us
Wed Jun  5 14:35:00 2019 [33167][1][INFO] Found language file: en_us.lang.php
Wed Jun  5 14:35:00 2019 [33167][1][INFO] Found custom language file: en_us.lang.php
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] Performing action: action_get MODULE: Alerts
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] get_full_list:  order_by = 'alerts.date_entered' and where = 'alerts.assigned_user_id = '1' AND is_read != '1''
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (modified_user_link).
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (created_by_link).
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (assigned_user_link).
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] process_order_by: (alerts.date_entered) does not have a vardef entry.
Wed Jun  5 14:35:00 2019 [33167][1][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 = '1' AND is_read != '1') AND alerts.deleted=0
Wed Jun  5 14:35:00 2019 [33167][1][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 = '1' AND is_read != '1') AND alerts.deleted=0
Wed Jun  5 14:35:00 2019 [33167][1][INFO] Query Execution Time:7.319450378418E-5
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] process_full_list_query: result is mysqli_result Object
(
    [current_field] => 0
    [field_count] => 23
    [lengths] => 
    [num_rows] => 0
    [type] => 0
)

Wed Jun  5 14:35:00 2019 [33167][1][DEPRECATED] Array
(
)

Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] Hook called: ::server_round_trip
Wed Jun  5 14:35:00 2019 [33167][1][DEBUG] Calling MySQLi::disconnect()
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] current_language is: en_us
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Found cache backend SugarCacheFile
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Found cache backend SugarCacheRedis
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Found cache backend SugarCacheWincache
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Found cache backend SugarCacheMemory
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Found cache backend SugarCacheMemcache
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Found cache backend SugarCacheMemcached
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Using cache backend SugarCacheMemcached, since 900 is less than 999
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Found cache backend SugarCachesMash
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Found cache backend SugarCacheAPC
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Found cache backend SugarCacheZend
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Found language file: en_us.lang.php
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Found custom language file: en_us.lang.php
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Query Execution Time:9.2983245849609E-5
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Query:SELECT category, name, value FROM config
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Query Execution Time:7.8916549682617E-5
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system'
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Query Execution Time:5.6982040405273E-5
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '87b4d0bd-e14a-adbd-3016-5bd1683c3c10'
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Query Execution Time:5.6028366088867E-5
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Hook called: ::after_entry_point
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Including module specific hook file for custom/modules
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Including Ext hook file for custom/application
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Hook called: ::after_session_start
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Unable to find SugarController:: LogView
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] We have an authenticated user id: 1
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Hook called: Users::before_retrieve
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Retrieve User : SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0
Wed Jun  5 14:35:19 2019 [34587][-none-][DEBUG] Limit Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 Start: 0 count: 1
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 LIMIT 0,1
Wed Jun  5 14:35:19 2019 [34587][-none-][INFO] Query Execution Time:0.00010895729064941
Wed Jun  5 14:35:19 2019 [34587][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
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:6.103515625E-5
Wed Jun  5 14:35:19 2019 [34587][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
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:3.504753112793E-5
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Wed Jun  5 14:35:19 2019 [34587][1][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 = '1'
                    AND ear.deleted = 0
                ORDER BY ear.reply_to_address, ear.primary_address DESC
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:9.1075897216797E-5
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: Users::after_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] FACTOR AUTH: User does`nt need factor auth
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Current user is: user_master
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Current user is: user_master
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] setting cookie ck_login_id_20 to 1
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] setting cookie ck_login_language_20 to en_us
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] current_language is: en_us
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Found language file: en_us.lang.php
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Found custom language file: en_us.lang.php
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Module:Configurator using file: LogView
Wed Jun  5 14:35:19 2019 [34587][1][DEPRECATED] Array
(
)

Wed Jun  5 14:35:19 2019 [34587][1][WARN] CSS File Dawn/yui.css not found
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT parent_id, parent_type FROM favorites WHERE assigned_user_id = '1' AND deleted = 0 ORDER BY date_entered DESC
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:0.00011301040649414
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: FP_events::before_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Retrieve FP_events : SELECT fp_events.* FROM fp_events  WHERE fp_events.id = 'b7fb135c-46b7-0795-2611-5cf55bd3581b' AND fp_events.deleted=0
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Limit Query:SELECT fp_events.* FROM fp_events  WHERE fp_events.id = 'b7fb135c-46b7-0795-2611-5cf55bd3581b' AND fp_events.deleted=0 Start: 0 count: 1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT fp_events.* FROM fp_events  WHERE fp_events.id = 'b7fb135c-46b7-0795-2611-5cf55bd3581b' AND fp_events.deleted=0 LIMIT 0,1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:7.2002410888672E-5
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] SugarBean[FP_events].load_relationships, Loading relationship (fp_event_locations_fp_events_1fp_event_locations_ida).
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT fp_event_locations_fp_events_1fp_event_locations_ida id  FROM fp_event_locations_fp_events_1_c  WHERE fp_event_locations_fp_events_1_c.fp_event_locations_fp_events_1fp_events_idb = 'b7fb135c-46b7-0795-2611-5cf55bd3581b' AND fp_event_locations_fp_events_1_c.deleted=0
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:8.2015991210938E-5
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: FP_Event_Locations::before_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Retrieve FP_Event_Locations : SELECT fp_event_locations.* FROM fp_event_locations  WHERE fp_event_locations.id = 'd61abd35-d861-8044-1224-5cf55b9827c1' AND fp_event_locations.deleted=0
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Limit Query:SELECT fp_event_locations.* FROM fp_event_locations  WHERE fp_event_locations.id = 'd61abd35-d861-8044-1224-5cf55b9827c1' AND fp_event_locations.deleted=0 Start: 0 count: 1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT fp_event_locations.* FROM fp_event_locations  WHERE fp_event_locations.id = 'd61abd35-d861-8044-1224-5cf55b9827c1' AND fp_event_locations.deleted=0 LIMIT 0,1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:5.6982040405273E-5
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] SugarBean[FP_Event_Locations].load_relationships, Loading relationship (assigned_user_id).
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] SugarBean.load_relationships, failed Loading relationship (assigned_user_id)
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] SugarBean[FP_Event_Locations].load_relationships, Loading relationship (assigned_user_id).
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] SugarBean.load_relationships, failed Loading relationship (assigned_user_id)
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: FP_Event_Locations::after_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT id ,fp_event_locations.name as fp_event_locations_fp_events_1_name , fp_event_locations.assigned_user_id owner FROM fp_event_locations WHERE deleted=0 AND id='d61abd35-d861-8044-1224-5cf55b9827c1'
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:4.6014785766602E-5
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: FP_events::after_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: AOW_WorkFlow::before_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Retrieve AOW_WorkFlow : SELECT aow_workflow.* FROM aow_workflow  WHERE aow_workflow.id = 'f2c28047-c09c-ba33-e7b5-5ce71f2f77d7' AND aow_workflow.deleted=0
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Limit Query:SELECT aow_workflow.* FROM aow_workflow  WHERE aow_workflow.id = 'f2c28047-c09c-ba33-e7b5-5ce71f2f77d7' AND aow_workflow.deleted=0 Start: 0 count: 1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT aow_workflow.* FROM aow_workflow  WHERE aow_workflow.id = 'f2c28047-c09c-ba33-e7b5-5ce71f2f77d7' AND aow_workflow.deleted=0 LIMIT 0,1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:8.8214874267578E-5
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: AOW_WorkFlow::after_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: Notes::before_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Retrieve Note : SELECT notes.* FROM notes  WHERE notes.id = '6ddfc204-bf54-ae37-492c-5c4b991ddc17' AND notes.deleted=0
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Limit Query:SELECT notes.* FROM notes  WHERE notes.id = '6ddfc204-bf54-ae37-492c-5c4b991ddc17' AND notes.deleted=0 Start: 0 count: 1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT notes.* FROM notes  WHERE notes.id = '6ddfc204-bf54-ae37-492c-5c4b991ddc17' AND notes.deleted=0 LIMIT 0,1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:7.1048736572266E-5
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] SugarBean[Note].load_relationships, Loading relationship (contact).
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: Notes::after_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: Accounts::before_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Including module specific hook file for custom/modules/Accounts
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Retrieve Account : SELECT accounts.*,accounts_cstm.* FROM accounts  LEFT JOIN accounts_cstm ON accounts.id = accounts_cstm.id_c  WHERE accounts.id = '5a706b7b-ef40-be35-c406-5c183856ce36' AND accounts.deleted=0
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Limit Query:SELECT accounts.*,accounts_cstm.* FROM accounts  LEFT JOIN accounts_cstm ON accounts.id = accounts_cstm.id_c  WHERE accounts.id = '5a706b7b-ef40-be35-c406-5c183856ce36' AND accounts.deleted=0 Start: 0 count: 1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT accounts.*,accounts_cstm.* FROM accounts  LEFT JOIN accounts_cstm ON accounts.id = accounts_cstm.id_c  WHERE accounts.id = '5a706b7b-ef40-be35-c406-5c183856ce36' AND accounts.deleted=0 LIMIT 0,1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:0.00010800361633301
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT a1.name from accounts a1, accounts a2 where a1.id = a2.parent_id and a2.id = '5a706b7b-ef40-be35-c406-5c183856ce36' and a1.deleted=0
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:5.1975250244141E-5
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] SugarBean[Account].load_relationships, Loading relationship (campaign_accounts).
Wed Jun  5 14:35:19 2019 [34587][1][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 = 'Accounts'
                    AND ear.bean_id = '5a706b7b-ef40-be35-c406-5c183856ce36'
                    AND ear.deleted = 0
                ORDER BY ear.reply_to_address, ear.primary_address DESC
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:7.3909759521484E-5
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: Accounts::after_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: Notes::before_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Retrieve Note : SELECT notes.* FROM notes  WHERE notes.id = '70f961fa-55fb-bb0f-5f07-5c16de84b1e7' AND notes.deleted=0
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Limit Query:SELECT notes.* FROM notes  WHERE notes.id = '70f961fa-55fb-bb0f-5f07-5c16de84b1e7' AND notes.deleted=0 Start: 0 count: 1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT notes.* FROM notes  WHERE notes.id = '70f961fa-55fb-bb0f-5f07-5c16de84b1e7' AND notes.deleted=0 LIMIT 0,1
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:6.103515625E-5
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] SugarBean[Note].load_relationships, Loading relationship (contact).
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Hook called: Notes::after_retrieve
Wed Jun  5 14:35:19 2019 [34587][1][DEBUG] Limit Query:SELECT item_id, item_summary, module_name, id FROM tracker WHERE id = (SELECT MAX(id) as id FROM tracker WHERE user_id = '1' AND deleted = 0 AND visible = 1) Start: 0 count: 50
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query:SELECT item_id, item_summary, module_name, id FROM tracker WHERE id = (SELECT MAX(id) as id FROM tracker WHERE user_id = '1' AND deleted = 0 AND visible = 1) LIMIT 0,50
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Query Execution Time:5.5074691772461E-5
Wed Jun  5 14:35:19 2019 [34587][1][INFO] Tracker: retrieving 10 items

[pgr]

Sorry, but that segment doesn’t seem to include anything relevant - no FATALs, no ERRORs, just one insignificant WARNing.

You need to try and find out which UI actions trigger those other messages that you showed earlier… so you can make them happen again and we can get a more complete picture.

[mookie_jam]

OK, I think I have located it now. Thank you very much for your help to solve this issue.

Wed Jun  5 17:00:02 2019 [27834][1][INFO] Connected to mail server id: 23f13959-8034-8494-f081-5c082505bdf2
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] Trying to connect to mailserver for [ HREU Info ]
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] Connected to mailserver
Wed Jun  5 17:00:02 2019 [27834][1][WARN] An Imap error detected: "IMAP search error"
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] -----> getNewMessageIds() got 1 new Messages
Wed Jun  5 17:00:02 2019 [27834][1][WARN] An Imap error detected: "IMAP expunge error"
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] In while loop of Inbound Emails
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] Using system default ImapHandler. Hint: Use any ImapHandlerInterface as dependency of InboundEmail
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] ImapHandlerFactory will using a ImapHandler
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] Hook called: InboundEmail::before_retrieve
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] Retrieve InboundEmail : SELECT inbound_email.* FROM inbound_email  WHERE inbound_email.id = '77f4d74c-8833-13d9-afd8-5c0825a2c452' AND inbound_email.deleted=0
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] Limit Query:SELECT inbound_email.* FROM inbound_email  WHERE inbound_email.id = '77f4d74c-8833-13d9-afd8-5c0825a2c452' AND inbound_email.deleted=0 Start: 0 count: 1
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query:SELECT inbound_email.* FROM inbound_email  WHERE inbound_email.id = '77f4d74c-8833-13d9-afd8-5c0825a2c452' AND inbound_email.deleted=0 LIMIT 0,1
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query Execution Time:0.00010299682617188
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] Hook called: InboundEmail::after_retrieve
Wed Jun  5 17:00:02 2019 [27834][1][WARN] Request ssl value not found.
Wed Jun  5 17:00:02 2019 [27834][1][WARN] Requested folder is not defined
Wed Jun  5 17:00:02 2019 [27834][1][ERROR] ImapHandler trying to use a non valid resource stream.
Wed Jun  5 17:00:02 2019 [27834][1][ERROR] ImapHandler trying to use a non valid resource stream.
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Connected to mail server id: 77f4d74c-8833-13d9-afd8-5c0825a2c452
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] Trying to connect to mailserver for [ HREU Sales ]
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] Connected to mailserver
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] -----> getNewMessageIds() got 213 new Messages
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query:SELECT * FROM folders WHERE id = '716a3857-0b99-a3a6-444d-5c082575d4ac' AND deleted = 0
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query Execution Time:0.014006853103638
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] InboundEmail processing 1 email 63-----------------------------------------------------------------------------------------
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] *********** InboundEmail doing dupe check.
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query:SELECT count(emails.id) AS c FROM emails WHERE emails.message_id = '0cddd2f3d895647ce209b3fbd9f0a580' and emails.deleted = 0
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query Execution Time:0.0094249248504639
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] InboundEmail found a duplicate email with ID (0cddd2f3d895647ce209b3fbd9f0a580)
Wed Jun  5 17:00:02 2019 [27834][1][INFO] InboundEmail found a duplicate email: <c30ad413-8d2c-3197-3b7c-503cbb476385@myweb.com>
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query:SELECT id from emails WHERE message_id ="0cddd2f3d895647ce209b3fbd9f0a580"AND mailbox_id = "77f4d74c-8833-13d9-afd8-5c0825a2c452"
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query Execution Time:0.00029897689819336
Wed Jun  5 17:00:02 2019 [27834][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] ***** On message [ 1 of 213 ] *****
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] InboundEmail processing 1 email 64-----------------------------------------------------------------------------------------
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] *********** InboundEmail doing dupe check.
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query:SELECT count(emails.id) AS c FROM emails WHERE emails.message_id = '1394ec8cbf708fd21c554473b104e289' and emails.deleted = 0
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query Execution Time:0.010802984237671
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] InboundEmail found a duplicate email with ID (1394ec8cbf708fd21c554473b104e289)
Wed Jun  5 17:00:02 2019 [27834][1][INFO] InboundEmail found a duplicate email: <DM6PR15MB2330E2845867E28ACF72E3AEFDDD0@DM6PR15MB2330.namprd15.prod.outlook.com>
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query:SELECT id from emails WHERE message_id ="1394ec8cbf708fd21c554473b104e289"AND mailbox_id = "77f4d74c-8833-13d9-afd8-5c0825a2c452"
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query Execution Time:0.0069530010223389
Wed Jun  5 17:00:02 2019 [27834][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] ***** On message [ 2 of 213 ] *****
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] InboundEmail processing 1 email 65-----------------------------------------------------------------------------------------
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] *********** InboundEmail doing dupe check.
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query:SELECT count(emails.id) AS c FROM emails WHERE emails.message_id = '8e41bfcd7a4f743c4c6830e39b9fbe51' and emails.deleted = 0
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query Execution Time:0.0033140182495117
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] InboundEmail found a duplicate email with ID (8e41bfcd7a4f743c4c6830e39b9fbe51)
Wed Jun  5 17:00:02 2019 [27834][1][INFO] InboundEmail found a duplicate email: <1090000272.20181121134257@irishgenius.net>
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query:SELECT id from emails WHERE message_id ="8e41bfcd7a4f743c4c6830e39b9fbe51"AND mailbox_id = "77f4d74c-8833-13d9-afd8-5c0825a2c452"
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query Execution Time:0.00030279159545898
Wed Jun  5 17:00:02 2019 [27834][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] ***** On message [ 3 of 213 ] *****
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] InboundEmail processing 1 email 66-----------------------------------------------------------------------------------------
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] *********** InboundEmail doing dupe check.
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query:SELECT count(emails.id) AS c FROM emails WHERE emails.message_id = '1d81b1ec189fb5f73154e3e7e87629a4' and emails.deleted = 0
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query Execution Time:0.002985954284668
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] InboundEmail found a duplicate email with ID (1d81b1ec189fb5f73154e3e7e87629a4)
Wed Jun  5 17:00:02 2019 [27834][1][INFO] InboundEmail found a duplicate email: <CA+po_rezKGWsUqu4dHL52BO+zbKj7EfD8pbJNycpOdbajr53sg@mail.gmail.com>
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query:SELECT id from emails WHERE message_id ="1d81b1ec189fb5f73154e3e7e87629a4"AND mailbox_id = "77f4d74c-8833-13d9-afd8-5c0825a2c452"
Wed Jun  5 17:00:02 2019 [27834][1][INFO] Query Execution Time:0.0029819011688232
Wed Jun  5 17:00:02 2019 [27834][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder
Wed Jun  5 17:00:02 2019 [27834][1][DEBUG] ***** On message [ 4 of 213 ] *****

I cut it on number 4. It laters repeats the same error for each 213 email.

[pgr]

Although that takes me to the part of the code that is being executed, which is useful, it is still hard to tell what is going wrong.

It looks like the folder it’s trying to save the email to, is not existent (but why would it try to do that?).

If you run on phpMyAdmin this query

SELECT * FROM folders WHERE id = '716a3857-0b99-a3a6-444d-5c082575d4ac' AND deleted = 0 

What do you get?

Or even just

SELECT * FROM folders 

Does everything look correct there?

Maybe you can try reconfiguring your IMAP, or playing with any options for folder subscriptions, something seems to have become corrupted there…

Good luck!

[cgwhite]

Hi folks, I have this same issue:

[FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder

I believe that it is to do with IMAP. I am seeing non existant old shared IMAP accounts and can’t see the IMAP sent folder. I can only believe that this message is where the IMAP module is trying to save to the IMAP server and can’t find the SENT folder on the server for some reason.

Question is. How do I reset the IMAP shared folders. I have tried removing the email accounts but they still show up if I go to the email client.

Your help as ever would be greatly appreciated.

Regards, Chris.

P.S. Further to this. I get a 403 message when trying to save an email template!

[pgr]

There are some tips and a link to the Github issue here

FOLDERS: addBean() is trying to save to a non-saved or non-existent folder

Hola a todos! Inicialmente comentaros que todavía no tengo SuiteCRM en producción, pero en las pruebas que he hecho hasta ahora, cuando nos llega un mail a la cuenta de grupo donde se crean los casos todo funciona correcto, pero cada minuto obtengo este error fatal: [15987][1][FATAL] *** FOLDERS: addBean() is trying to save to a non-saved or non-existent folder. Tengo la cuenta sincronizada con los folder de imap y no sé si el problema puede ser de mi servidor IMAP o alguna…

[cgwhite]

Thank you. I will look at that. I can confirm that having removed the shared mail account this stops the log filling with these lines. I have repair and rebuilt the files and will now add a shared account again to see what happens.

[cgwhite]

OK, removing the shared email account has stopped the log file filling up with the FATAL message, but I still have the following when I click on the button on the top of the email client to select the email account that I want to use: (I have added a new shared account called admin@9659.uk)

I only now have the admin@9659.uk account in the system. The others are not configured.

Regards, Chris.

[cgwhite]

Well, that is conclusive, this is being caused by the “Import Emails Automatically” check box in group email settings. If you don’t import emails automatically it stops. It is absolutely right it can’t save the imported emails as there is no associated record, (contact/lead/opportunity) for it to save the email too.

This presumably is a bug. How do we get it fixed as it would be great to use the import automatically function.