Email Configuration issue

DestinKS · 9 October 2019 21:42

Hello all,

I’m currently experiencing an issue with the email setting/outbound email in the below versions:

Version 7.11.7
Sugar Version 6.5.25 (Build 344)

I’ve read multiple threads and tried numerous troubleshooting steps but no luck. The issue that I’m experiencing is that my test email will not send. I would be get the “One moment please…” then the message would disappear. I don’t get the notification that a email was sent. Also everything time I make a change to the SMTP Mail Server and username then save it. It resets back to the previous setting which is stmp.office365.com. Can someone please help me? I’ve attached some screenshots.

pgr · 10 October 2019 15:04

I’ve seen a thread recently where the problem seemed to be specific to office365 servers. Can you try a different email address, on a different provider, just as a test?

DestinKS · 10 October 2019 18:27

I’m trying to use a gmail but every time I press save it reverts it back to Office365 preferences. I’ve also tried sending a test email but it does the same and reverts everything to Office365.

pgr · 10 October 2019 21:29

Can you please get me a transcript of your logs at the moment when you save Gmail settings and it reverts back to office365 settings?

DestinKS · 10 October 2019 22:54

Here is a screenshot of the logs.

ashish · 11 October 2019 05:13

Hi,

Please perform the quick repair and then try to update the email setting in the Incognito browser.

If you still face the issue, please let me know.

Thank you!

pgr · 11 October 2019 09:14

Thanks for that log, but you give me messages across many minutes, I would need to know which one happens exactly when you “trying to use a gmail but every time I press save it reverts it back to Office365 preferences”

Also, please go first in your Admin / System settings and raise your log level to “debug”.

This will generate a LOT of output, you better send me the log as text, not as screenshots.

Thank you for your help looking for this bug.

DestinKS · 11 October 2019 12:35

@pgr here are the logs under the debug level.

Fri Oct 11 12:29:55 2019 [60625][1][DEBUG] Hook called: ::server_round_trip
Fri Oct 11 12:29:55 2019 [60625][1][DEBUG] Calling MySQLi::disconnect()
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] current_language is: en_us
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Found cache backend SugarCacheMemcached
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Found cache backend SugarCacheMemcache
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Found cache backend SugarCacheFile
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Found cache backend SugarCacheAPC
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Found cache backend SugarCacheMemory
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Found cache backend SugarCachesMash
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Found cache backend SugarCacheWincache
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Found cache backend SugarCacheRedis
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Found cache backend SugarCacheZend
Fri Oct 11 12:29:58 2019 [60626][-none-][INFO] Found language file: en_us.lang.php
Fri Oct 11 12:29:58 2019 [60626][-none-][INFO] Found custom language file: en_us.lang.php
Fri Oct 11 12:29:58 2019 [60626][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Fri Oct 11 12:29:58 2019 [60626][-none-][INFO] Query Execution Time:0.0002138614654541
Fri Oct 11 12:29:58 2019 [60626][-none-][INFO] Query:SELECT category, name, value FROM config
Fri Oct 11 12:29:58 2019 [60626][-none-][INFO] Query Execution Time:0.00024294853210449
Fri Oct 11 12:29:58 2019 [60626][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system'
Fri Oct 11 12:29:58 2019 [60626][-none-][INFO] Query Execution Time:0.00016283988952637
Fri Oct 11 12:29:58 2019 [60626][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705'
Fri Oct 11 12:29:58 2019 [60626][-none-][INFO] Query Execution Time:0.00014781951904297
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Hook called: ::after_entry_point
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Including module specific hook file for custom/modules
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Including Ext hook file for custom/application
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Hook called: ::after_session_start
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Unable to find SugarController:: get
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Hook called: ::server_round_trip
Fri Oct 11 12:29:58 2019 [60626][-none-][DEBUG] Calling MySQLi::disconnect()
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] current_language is: en_us
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Found cache backend SugarCacheMemcached
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Found cache backend SugarCacheMemcache
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Found cache backend SugarCacheFile
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Found cache backend SugarCacheAPC
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Found cache backend SugarCacheMemory
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Found cache backend SugarCachesMash
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Found cache backend SugarCacheWincache
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Found cache backend SugarCacheRedis
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Found cache backend SugarCacheZend
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Found language file: en_us.lang.php
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Found custom language file: en_us.lang.php
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Query Execution Time:0.0002138614654541
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Query:SELECT category, name, value FROM config
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Query Execution Time:0.00018405914306641
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system'
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Query Execution Time:0.00012707710266113
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705'
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Query Execution Time:0.0001530647277832
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Hook called: ::after_entry_point
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Including module specific hook file for custom/modules
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Including Ext hook file for custom/application
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Hook called: ::after_session_start
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Unable to find SugarController:: testOutboundEmail
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] We have an authenticated user id: 1
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Hook called: Users::before_retrieve
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Retrieve User : SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0
Fri Oct 11 12:30:07 2019 [60675][-none-][DEBUG] Limit Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 Start: 0 count: 1
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 LIMIT 0,1
Fri Oct 11 12:30:07 2019 [60675][-none-][INFO] Query Execution Time:0.00026202201843262
Fri Oct 11 12:30:07 2019 [60675][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
Fri Oct 11 12:30:07 2019 [60675][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Fri Oct 11 12:30:07 2019 [60675][1][INFO] Query Execution Time:0.00020980834960938
Fri Oct 11 12:30:07 2019 [60675][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
Fri Oct 11 12:30:07 2019 [60675][1][INFO] Query Execution Time:0.0033960342407227
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Fri Oct 11 12:30:07 2019 [60675][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
Fri Oct 11 12:30:07 2019 [60675][1][INFO] Query Execution Time:0.00038599967956543
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] Hook called: Users::after_retrieve
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] FACTOR AUTH: User does`nt need factor auth
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] Current user is: kinadmin
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] Current user is: kinadmin
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] setting cookie ck_login_id_20 to 1
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] setting cookie ck_login_language_20 to en_us
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] current_language is: en_us
Fri Oct 11 12:30:07 2019 [60675][1][INFO] Found language file: en_us.lang.php
Fri Oct 11 12:30:07 2019 [60675][1][INFO] Found custom language file: en_us.lang.php
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] Module:EmailMan using file: testOutboundEmail
Fri Oct 11 12:30:07 2019 [60675][1][DEPRECATED] Array
(
)

Fri Oct 11 12:30:07 2019 [60675][1][INFO] Query:SELECT id FROM outbound_email WHERE user_id = '1' 
Fri Oct 11 12:30:07 2019 [60675][1][INFO] Query Execution Time:0.00026106834411621
Fri Oct 11 12:30:07 2019 [60675][1][INFO] Query:SELECT * FROM outbound_email WHERE id = '3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705'
Fri Oct 11 12:30:07 2019 [60675][1][INFO] Query Execution Time:0.00015997886657715
Fri Oct 11 12:30:07 2019 [60675][1][FATAL] SugarPHPMailer encountered an error: SMTP Error: Could not connect to SMTP host.
Fri Oct 11 12:30:07 2019 [60675][1][FATAL] SugarPHPMailer encountered an error: SMTP Error: Could not connect to SMTP host.
Fri Oct 11 12:30:07 2019 [60675][1][ERROR] send: PHPMailer Exception: { <strong>SMTP Error: Could not connect to SMTP host.</strong><br />
 }
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] Hook called: EmailMan::after_ui_frame
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] Creating new instance of hook class hooks without parameters
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] Hook called: ::after_ui_footer
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] Hook called: ::server_round_trip
Fri Oct 11 12:30:07 2019 [60675][1][DEBUG] Calling MySQLi::disconnect()
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] current_language is: en_us
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Found cache backend SugarCacheMemcached
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Found cache backend SugarCacheMemcache
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Found cache backend SugarCacheFile
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Found cache backend SugarCacheAPC
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Found cache backend SugarCacheMemory
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Found cache backend SugarCachesMash
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Found cache backend SugarCacheWincache
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Found cache backend SugarCacheRedis
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Found cache backend SugarCacheZend
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Found language file: en_us.lang.php
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Found custom language file: en_us.lang.php
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Query Execution Time:0.00022506713867188
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Query:SELECT category, name, value FROM config
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Query Execution Time:0.00086307525634766
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system'
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Query Execution Time:0.00017499923706055
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705'
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Query Execution Time:0.00014805793762207
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Hook called: ::after_entry_point
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Including module specific hook file for custom/modules
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Including Ext hook file for custom/application
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Hook called: ::after_session_start
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Unable to find SugarController:: LogView
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] We have an authenticated user id: 1
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Hook called: Users::before_retrieve
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Retrieve User : SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0
Fri Oct 11 12:30:15 2019 [60684][-none-][DEBUG] Limit Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 Start: 0 count: 1
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 LIMIT 0,1
Fri Oct 11 12:30:15 2019 [60684][-none-][INFO] Query Execution Time:0.00026106834411621
Fri Oct 11 12:30:15 2019 [60684][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
Fri Oct 11 12:30:15 2019 [60684][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Fri Oct 11 12:30:15 2019 [60684][1][INFO] Query Execution Time:0.00021982192993164
Fri Oct 11 12:30:15 2019 [60684][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
Fri Oct 11 12:30:15 2019 [60684][1][INFO] Query Execution Time:0.00014185905456543
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Fri Oct 11 12:30:15 2019 [60684][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
Fri Oct 11 12:30:15 2019 [60684][1][INFO] Query Execution Time:0.00039196014404297
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] Hook called: Users::after_retrieve
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] FACTOR AUTH: User does`nt need factor auth
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] Current user is: kinadmin
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] Current user is: kinadmin
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] setting cookie ck_login_id_20 to 1
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] setting cookie ck_login_language_20 to en_us
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] current_language is: en_us
Fri Oct 11 12:30:15 2019 [60684][1][INFO] Found language file: en_us.lang.php
Fri Oct 11 12:30:15 2019 [60684][1][INFO] Found custom language file: en_us.lang.php
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] Module:Configurator using file: LogView
Fri Oct 11 12:30:15 2019 [60684][1][DEPRECATED] Array
(
)

Fri Oct 11 12:30:15 2019 [60684][1][WARN] CSS File Day/yui.css not found
Fri Oct 11 12:30:15 2019 [60684][1][INFO] Query:SELECT parent_id, parent_type FROM favorites WHERE assigned_user_id = '1' AND deleted = 0 ORDER BY date_entered DESC
Fri Oct 11 12:30:15 2019 [60684][1][INFO] Query Execution Time:0.00022602081298828
Fri Oct 11 12:30:15 2019 [60684][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
Fri Oct 11 12:30:15 2019 [60684][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
Fri Oct 11 12:30:15 2019 [60684][1][INFO] Query Execution Time:0.00034904479980469
Fri Oct 11 12:30:15 2019 [60684][1][INFO] Tracker: retrieving 10 items
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] Hook called: Configurator::after_ui_frame
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] Creating new instance of hook class hooks without parameters
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Fri Oct 11 12:30:15 2019 [60684][1][WARN] Undefined index: server_unique_key
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] Hook called: ::after_ui_footer
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] Hook called: ::server_round_trip
Fri Oct 11 12:30:15 2019 [60684][1][DEBUG] Calling MySQLi::disconnect()
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] current_language is: en_us
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Found cache backend SugarCacheMemcached
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Found cache backend SugarCacheMemcache
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Found cache backend SugarCacheFile
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Found cache backend SugarCacheAPC
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Found cache backend SugarCacheMemory
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Found cache backend SugarCachesMash
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Found cache backend SugarCacheWincache
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Found cache backend SugarCacheRedis
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Found cache backend SugarCacheZend
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Found language file: en_us.lang.php
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Found custom language file: en_us.lang.php
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Query Execution Time:0.00021505355834961
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Query:SELECT category, name, value FROM config
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Query Execution Time:0.00017714500427246
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system'
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Query Execution Time:0.00017094612121582
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705'
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Query Execution Time:0.0001530647277832
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Hook called: ::after_entry_point
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Including module specific hook file for custom/modules
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Including Ext hook file for custom/application
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Hook called: ::after_session_start
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Unable to find SugarController:: LogView
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] We have an authenticated user id: 1
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Hook called: Users::before_retrieve
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Retrieve User : SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0
Fri Oct 11 12:30:17 2019 [60688][-none-][DEBUG] Limit Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 Start: 0 count: 1
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Query:SELECT users.* FROM users  WHERE users.id = '1' AND users.deleted=0 LIMIT 0,1
Fri Oct 11 12:30:17 2019 [60688][-none-][INFO] Query Execution Time:0.00023198127746582
Fri Oct 11 12:30:17 2019 [60688][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
Fri Oct 11 12:30:17 2019 [60688][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Fri Oct 11 12:30:17 2019 [60688][1][INFO] Query Execution Time:0.00023198127746582
Fri Oct 11 12:30:17 2019 [60688][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
Fri Oct 11 12:30:17 2019 [60688][1][INFO] Query Execution Time:0.0001530647277832
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Fri Oct 11 12:30:17 2019 [60688][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
Fri Oct 11 12:30:17 2019 [60688][1][INFO] Query Execution Time:0.00039005279541016
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] Hook called: Users::after_retrieve
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] FACTOR AUTH: User does`nt need factor auth
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] Current user is: kinadmin
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] Current user is: kinadmin
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] setting cookie ck_login_id_20 to 1
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] setting cookie ck_login_language_20 to en_us
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] current_language is: en_us
Fri Oct 11 12:30:17 2019 [60688][1][INFO] Found language file: en_us.lang.php
Fri Oct 11 12:30:17 2019 [60688][1][INFO] Found custom language file: en_us.lang.php
Fri Oct 11 12:30:17 2019 [60688][1][DEBUG] Module:Configurator using file: LogView
Fri Oct 11 12:30:17 2019 [60688][1][DEPRECATED] Array
(
)

Fri Oct 11 12:30:17 2019 [60688][1][WARN] CSS File Day/yui.css not found
Fri Oct 11 12:30:17 2019 [60688][1][INFO] Query:SELECT parent_id, parent_type FROM favorites WHERE assigned_user_id = '1' AND deleted = 0 ORDER BY date_entered DESC
Fri Oct 11 12:30:17 2019 [60688][1][INFO] Query Execution Time:0.00023794174194336
Fri Oct 11 12:30:17 2019 [60688][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
Fri Oct 11 12:30:17 2019 [60688][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
Fri Oct 11 12:30:17 2019 [60688][1][INFO] Query Execution Time:0.00040793418884277
Fri Oct 11 12:30:17 2019 [60688][1][INFO] Tracker: retrieving 10 items

@ashish@outrightcrm.com

I’ve performed a backup, cleared the cache, and did a repair already same results. I’ve even tried a incognito browser as well.

pgr · 11 October 2019 15:19

Can your server ping these two addresses correctly?

smtp.gmail.com
smtp.office365.com

Are you using “From name” and “From address” that matches what you have in the respective accounts? For example, if your email account is me@gmail.com, you can’t use a “From address” that is "joe@gmail.com" or something else.

DestinKS · 11 October 2019 20:33

Here are the pings results. Looks fine to me. Yes, I’m using the same email address for both “From name” and “From address”

pgr · 15 October 2019 08:49

Hello @DestinKS, were you aabel to get any progress on this?

I am a bit out of ideas to help you. If you are really stumped, maybe you can try uncommenting these lines here:

https://github.com/salesagility/SuiteCRM/blob/master/include/SugarPHPMailer.php#L457

https://github.com/salesagility/SuiteCRM/blob/master/include/SugarPHPMailer.php#L497-L502

This will put some more information in your logs to help yo troubleshoot.

DestinKS · 15 October 2019 13:01

Hello @pgr no update on the issue. I’m still experiencing the same results after uncommenting those two lines.Below are the logs after making those changes.

Tue Oct 15 12:53:17 2019 [51405][1][DEBUG] smtp send: { 3: Connection: closed }
Tue Oct 15 12:53:17 2019 [51405][1][DEBUG] smtp send: { 3: SMTP Error: Could not connect to SMTP host. }
Tue Oct 15 12:53:17 2019 [51405][1][DEBUG] ------------ Exiting SugarMailer send
Tue Oct 15 12:53:17 2019 [51405][1][DEBUG] Hook called: EmailMan::after_ui_frame
Tue Oct 15 12:53:17 2019 [51405][1][DEBUG] Creating new instance of hook class hooks without parameters
Tue Oct 15 12:53:17 2019 [51405][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Tue Oct 15 12:53:17 2019 [51405][1][DEBUG] Hook called: ::after_ui_footer
Tue Oct 15 12:53:17 2019 [51405][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Tue Oct 15 12:53:17 2019 [51405][1][DEBUG] Hook called: ::server_round_trip
Tue Oct 15 12:53:17 2019 [51405][1][DEBUG] Calling MySQLi::disconnect()
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] current_language is: en_us
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Found cache backend SugarCacheMemcached
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Found cache backend SugarCacheMemcache
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Found cache backend SugarCacheFile
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Found cache backend SugarCacheAPC
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Found cache backend SugarCacheMemory
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Found cache backend SugarCachesMash
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Found cache backend SugarCacheWincache
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Found cache backend SugarCacheRedis
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Found cache backend SugarCacheZend
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Found language file: en_us.lang.php
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Found custom language file: en_us.lang.php
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = ‘Active’ and deleted = 0
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Query Execution Time:0.00022697448730469
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Query:SELECT category, name, value FROM config
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Query Execution Time:0.00023698806762695
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = ‘system’
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Query Execution Time:0.0001368522644043
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = ‘3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705’
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Query Execution Time:0.0001530647277832
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Hook called: ::after_entry_point
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Including module specific hook file for custom/modules
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Including Ext hook file for custom/application
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Hook called: ::after_session_start
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Unable to find SugarController:: LogView
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] We have an authenticated user id: 1
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Hook called: Users::before_retrieve
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Retrieve User : SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0
Tue Oct 15 12:53:20 2019 [51409][-none-][DEBUG] Limit Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 Start: 0 count: 1
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Oct 15 12:53:20 2019 [51409][-none-][INFO] Query Execution Time:0.00027203559875488
Tue Oct 15 12:53:20 2019 [51409][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
Tue Oct 15 12:53:20 2019 [51409][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Tue Oct 15 12:53:20 2019 [51409][1][INFO] Query Execution Time:0.0002591609954834
Tue Oct 15 12:53:20 2019 [51409][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
Tue Oct 15 12:53:20 2019 [51409][1][INFO] Query Execution Time:0.00018215179443359
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Tue Oct 15 12:53:20 2019 [51409][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
Tue Oct 15 12:53:20 2019 [51409][1][INFO] Query Execution Time:0.00035905838012695
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] Hook called: Users::after_retrieve
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] FACTOR AUTH: User does`nt need factor auth
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] Current user is: kinadmin
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] Current user is: kinadmin
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] setting cookie ck_login_id_20 to 1
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] setting cookie ck_login_language_20 to en_us
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] current_language is: en_us
Tue Oct 15 12:53:20 2019 [51409][1][INFO] Found language file: en_us.lang.php
Tue Oct 15 12:53:20 2019 [51409][1][INFO] Found custom language file: en_us.lang.php
Tue Oct 15 12:53:20 2019 [51409][1][DEBUG] Module:Configurator using file: LogView
Tue Oct 15 12:53:20 2019 [51409][1][DEPRECATED] Array
(
)

Tue Oct 15 12:53:20 2019 [51409][1][WARN] CSS File Day/yui.css not found
Tue Oct 15 12:53:20 2019 [51409][1][INFO] Query:SELECT parent_id, parent_type FROM favorites WHERE assigned_user_id = ‘1’ AND deleted = 0 ORDER BY date_entered DESC
Tue Oct 15 12:53:20 2019 [51409][1][INFO] Query Execution Time:0.00021100044250488
Tue Oct 15 12:53:20 2019 [51409][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
Tue Oct 15 12:53:20 2019 [51409][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
Tue Oct 15 12:53:20 2019 [51409][1][INFO] Query Execution Time:0.00030708312988281
Tue Oct 15 12:53:20 2019 [51409][1][INFO] Tracker: retrieving 10 items

pgr · 19 October 2019 17:52

You need to uncomment this entire block


        /* uncomment this to send full log into suitecrm.log:
        $line = strtok($this->fullSmtpLog, "\n");
        while ($line !== false) {
             $GLOBALS['log']->debug("smtp send: { $line }");
             $line = strtok( "\n" );
        }
        $GLOBALS['log']->debug("------------ Exiting SugarMailer send");
        */

by removing the /* and */ and the text, making it look like this:


       
        $line = strtok($this->fullSmtpLog, "\n");
        while ($line !== false) {
             $GLOBALS['log']->debug("smtp send: { $line }");
             $line = strtok( "\n" );
        }
        $GLOBALS['log']->debug("------------ Exiting SugarMailer send");

This will generate a bunch of lines starting with “smtp send” in the logs, for each email attempted. This is the dialogue with the SMTP server and might give you some clues.

The other line earlier on will produce a single line in the logs, starting with “PHPMailer Send Function” and showing the parameters going into the send command. This allows you to check if your email configuration (from address, from name, etc) is reaching that critical point correctly.

d1white · 22 October 2019 11:27

Thanks
I had some difficulties with Email Configuration, but now they’re solved.

DestinKS · 22 October 2019 13:02

@pgr I actually already had those lines uncommitted and still receiving the same errors below in the log:

Tue Oct 22 12:57:18 2019 [130214][1][DEBUG] smtp send: { 3: Connection: closed }
Tue Oct 22 12:57:18 2019 [130214][1][DEBUG] smtp send: { 3: SMTP Error: Could not connect to SMTP host. }
Tue Oct 22 12:57:18 2019 [130214][1][DEBUG] ------------ Exiting SugarMailer send
Tue Oct 22 12:57:18 2019 [130214][1][DEBUG] Hook called: EmailMan::after_ui_frame
Tue Oct 22 12:57:18 2019 [130214][1][DEBUG] Creating new instance of hook class hooks without parameters
Tue Oct 22 12:57:18 2019 [130214][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Tue Oct 22 12:57:18 2019 [130214][1][DEBUG] Hook called: ::after_ui_footer
Tue Oct 22 12:57:18 2019 [130214][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Tue Oct 22 12:57:18 2019 [130214][1][DEBUG] Hook called: ::server_round_trip
Tue Oct 22 12:57:18 2019 [130214][1][DEBUG] Calling MySQLi::disconnect()
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] current_language is: en_us
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Found cache backend SugarCacheMemcached
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Found cache backend SugarCacheMemcache
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Found cache backend SugarCacheFile
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Found cache backend SugarCacheAPC
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Found cache backend SugarCacheMemory
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Found cache backend SugarCachesMash
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Found cache backend SugarCacheWincache
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Found cache backend SugarCacheRedis
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Found cache backend SugarCacheZend
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Found language file: en_us.lang.php
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Found custom language file: en_us.lang.php
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = ‘Active’ and deleted = 0
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Query Execution Time:0.00022602081298828
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Query:SELECT category, name, value FROM config
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Query Execution Time:0.0001828670501709
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = ‘system’
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Query Execution Time:0.00012397766113281
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = ‘3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705’
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Query Execution Time:0.00014901161193848
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Hook called: ::after_entry_point
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Including module specific hook file for custom/modules
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Including Ext hook file for custom/application
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Hook called: ::after_session_start
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Unable to find SugarController:: Popup
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] We have an authenticated user id: 1
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Hook called: Users::before_retrieve
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Retrieve User : SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0
Tue Oct 22 12:57:20 2019 [130216][-none-][DEBUG] Limit Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 Start: 0 count: 1
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Oct 22 12:57:20 2019 [130216][-none-][INFO] Query Execution Time:0.00032210350036621
Tue Oct 22 12:57:20 2019 [130216][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
Tue Oct 22 12:57:20 2019 [130216][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Tue Oct 22 12:57:20 2019 [130216][1][INFO] Query Execution Time:0.00027203559875488
Tue Oct 22 12:57:20 2019 [130216][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
Tue Oct 22 12:57:20 2019 [130216][1][INFO] Query Execution Time:0.00015902519226074
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Tue Oct 22 12:57:20 2019 [130216][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
Tue Oct 22 12:57:20 2019 [130216][1][INFO] Query Execution Time:0.0004420280456543
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] Hook called: Users::after_retrieve
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] FACTOR AUTH: User does`nt need factor auth
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] setting cookie ck_login_id_20 to 1
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] setting cookie ck_login_language_20 to en_us
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] current_language is: en_us
Tue Oct 22 12:57:20 2019 [130216][1][INFO] Found language file: en_us.lang.php
Tue Oct 22 12:57:20 2019 [130216][1][INFO] Found custom language file: en_us.lang.php
Tue Oct 22 12:57:20 2019 [130216][1][DEBUG] rebuilding cache for Audit
Tue Oct 22 12:57:20 2019 [130216][1][INFO] Query:SELECT * FROM fields_meta_data WHERE custom_module=‘Audit’ AND deleted = 0
Tue Oct 22 12:57:20 2019 [130216][1][INFO] Query Execution Time:0.0002751350402832
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Using Action View Map:popup
Tue Oct 22 12:57:21 2019 [130216][1][DEPRECATED] Array
(
)

Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] rebuilding cache for Audit
Tue Oct 22 12:57:21 2019 [130216][1][INFO] Query:SELECT * FROM fields_meta_data WHERE custom_module=‘Audit’ AND deleted = 0
Tue Oct 22 12:57:21 2019 [130216][1][INFO] Query Execution Time:0.0003809928894043
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] rebuilding cache for Audit
Tue Oct 22 12:57:21 2019 [130216][1][INFO] Query:SELECT * FROM fields_meta_data WHERE custom_module=‘Audit’ AND deleted = 0
Tue Oct 22 12:57:21 2019 [130216][1][INFO] Query Execution Time:0.00017404556274414
Tue Oct 22 12:57:21 2019 [130216][1][WARN] SugarBean constructor error: Object has not fields in dictionary. Object name was: Audit
Tue Oct 22 12:57:21 2019 [130216][1][FATAL] SugarBean::populateDefaultValues $field_defs should be an array
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Hook called: OutboundEmailAccounts::before_retrieve
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Retrieve OutboundEmailAccounts : SELECT outbound_email.* FROM outbound_email WHERE outbound_email.id = ‘da4ddb6b-6acd-bb0e-67ab-5d9e362a9ece’ AND outbound_email.deleted=0
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Limit Query:SELECT outbound_email.* FROM outbound_email WHERE outbound_email.id = ‘da4ddb6b-6acd-bb0e-67ab-5d9e362a9ece’ AND outbound_email.deleted=0 Start: 0 count: 1
Tue Oct 22 12:57:21 2019 [130216][1][INFO] Query:SELECT outbound_email.* FROM outbound_email WHERE outbound_email.id = ‘da4ddb6b-6acd-bb0e-67ab-5d9e362a9ece’ AND outbound_email.deleted=0 LIMIT 0,1
Tue Oct 22 12:57:21 2019 [130216][1][INFO] Query Execution Time:0.00018620491027832
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] SugarBean[OutboundEmailAccounts].load_relationships, Loading relationship (assigned_user_id).
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] SugarBean.load_relationships, failed Loading relationship (assigned_user_id)
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] SugarBean[OutboundEmailAccounts].load_relationships, Loading relationship (assigned_user_id).
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] SugarBean.load_relationships, failed Loading relationship (assigned_user_id)
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Hook called: OutboundEmailAccounts::after_retrieve
Tue Oct 22 12:57:21 2019 [130216][1][INFO] Query:SELECT outbound_email_audit., users.user_name FROM outbound_email_audit, users WHERE outbound_email_audit.created_by = users.id AND outbound_email_audit.parent_id = ‘da4ddb6b-6acd-bb0e-67ab-5d9e362a9ece’ order by outbound_email_audit.date_created desc
Tue Oct 22 12:57:21 2019 [130216][1][INFO] Query Execution Time:0.0002748966217041
Tue Oct 22 12:57:21 2019 [130216][1][WARN] CSS File Day/yui.css not found
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Hook called: Audit::after_ui_frame
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Creating new instance of hook class hooks without parameters
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Hook called: ::after_ui_footer
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Hook called: ::server_round_trip
Tue Oct 22 12:57:21 2019 [130216][1][DEBUG] Calling MySQLi::disconnect()
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] current_language is: en_us
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Found cache backend SugarCacheMemcached
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Found cache backend SugarCacheMemcache
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Found cache backend SugarCacheFile
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Found cache backend SugarCacheAPC
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Found cache backend SugarCacheMemory
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Found cache backend SugarCachesMash
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Found cache backend SugarCacheWincache
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Found cache backend SugarCacheRedis
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Found cache backend SugarCacheZend
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Found language file: en_us.lang.php
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Found custom language file: en_us.lang.php
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = ‘Active’ and deleted = 0
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Query Execution Time:0.00023198127746582
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Query:SELECT category, name, value FROM config
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Query Execution Time:0.00024914741516113
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = ‘system’
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Query Execution Time:0.00014185905456543
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = ‘3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705’
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Query Execution Time:0.00016593933105469
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Hook called: ::after_entry_point
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Including module specific hook file for custom/modules
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Including Ext hook file for custom/application
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Hook called: ::after_session_start
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Unable to find SugarController:: index
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] We have an authenticated user id: 1
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Hook called: Users::before_retrieve
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Retrieve User : SELECT users. FROM users WHERE users.id = ‘1’ AND users.deleted=0
Tue Oct 22 12:57:21 2019 [130217][-none-][DEBUG] Limit Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 Start: 0 count: 1
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Oct 22 12:57:21 2019 [130217][-none-][INFO] Query Execution Time:0.00042009353637695
Tue Oct 22 12:57:21 2019 [130217][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
Tue Oct 22 12:57:21 2019 [130217][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Tue Oct 22 12:57:21 2019 [130217][1][INFO] Query Execution Time:0.00025105476379395
Tue Oct 22 12:57:21 2019 [130217][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
Tue Oct 22 12:57:21 2019 [130217][1][INFO] Query Execution Time:0.00016212463378906
Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Tue Oct 22 12:57:21 2019 [130217][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
Tue Oct 22 12:57:21 2019 [130217][1][INFO] Query Execution Time:0.00055694580078125
Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] Hook called: Users::after_retrieve
Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] FACTOR AUTH: User doesnt need factor auth Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] Current user is: kinadmin Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] Current user is: kinadmin Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] setting cookie ck_login_id_20 to 1 Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] setting cookie ck_login_language_20 to en_us Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] current_language is: en_us Tue Oct 22 12:57:21 2019 [130217][1][INFO] Found language file: en_us.lang.php Tue Oct 22 12:57:21 2019 [130217][1][INFO] Found custom language file: en_us.lang.php Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] Hook called: ::server_round_trip Tue Oct 22 12:57:21 2019 [130217][1][DEBUG] Calling MySQLi::disconnect() Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] current_language is: en_us Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Found cache backend SugarCacheMemcached Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Found cache backend SugarCacheMemcache Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Found cache backend SugarCacheFile Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Found cache backend SugarCacheAPC Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Found cache backend SugarCacheMemory Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000 Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Found cache backend SugarCachesMash Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Found cache backend SugarCacheWincache Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Found cache backend SugarCacheRedis Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Found cache backend SugarCacheZend Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Found language file: en_us.lang.php Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Found custom language file: en_us.lang.php Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0 Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Query Execution Time:0.00021696090698242 Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Query:SELECT category, name, value FROM config Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Query Execution Time:0.0002131462097168 Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system' Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Query Execution Time:0.00011897087097168 Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705' Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Query Execution Time:0.00014305114746094 Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Hook called: ::after_entry_point Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Including module specific hook file for custom/modules Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Including Ext hook file for custom/application Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Hook called: ::after_session_start Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Unable to find SugarController:: index Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] We have an authenticated user id: 1 Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Hook called: Users::before_retrieve Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Including module specific hook file for custom/modules/Users Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Retrieve User : SELECT users.* FROM users WHERE users.id = '1' AND users.deleted=0 Tue Oct 22 12:57:24 2019 [130230][-none-][DEBUG] Limit Query:SELECT users.* FROM users WHERE users.id = '1' AND users.deleted=0 Start: 0 count: 1 Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Query:SELECT users.* FROM users WHERE users.id = '1' AND users.deleted=0 LIMIT 0,1 Tue Oct 22 12:57:24 2019 [130230][-none-][INFO] Query Execution Time:0.00025486946105957 Tue Oct 22 12:57:24 2019 [130230][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 Tue Oct 22 12:57:24 2019 [130230][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC Tue Oct 22 12:57:24 2019 [130230][1][INFO] Query Execution Time:0.00022292137145996 Tue Oct 22 12:57:24 2019 [130230][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 Tue Oct 22 12:57:24 2019 [130230][1][INFO] Query Execution Time:0.00014495849609375 Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link). Tue Oct 22 12:57:24 2019 [130230][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 Tue Oct 22 12:57:24 2019 [130230][1][INFO] Query Execution Time:0.00034403800964355 Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] Hook called: Users::after_retrieve Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] FACTOR AUTH: ------------------------------------------------------------- Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH --------------------- Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] FACTOR AUTH: ------------------------------------------------------------- Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] FACTOR AUTH: User doesnt need factor auth
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] setting cookie ck_login_id_20 to 1
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] setting cookie ck_login_language_20 to en_us
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] current_language is: en_us
Tue Oct 22 12:57:24 2019 [130230][1][INFO] Found language file: en_us.lang.php
Tue Oct 22 12:57:24 2019 [130230][1][INFO] Found custom language file: en_us.lang.php
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] Module:Administration using file: index
Tue Oct 22 12:57:24 2019 [130230][1][DEPRECATED] Array
(
)

Tue Oct 22 12:57:24 2019 [130230][1][WARN] CSS File Day/yui.css not found
Tue Oct 22 12:57:24 2019 [130230][1][INFO] Query:SELECT parent_id, parent_type FROM favorites WHERE assigned_user_id = ‘1’ AND deleted = 0 ORDER BY date_entered DESC
Tue Oct 22 12:57:24 2019 [130230][1][INFO] Query Execution Time:0.00023698806762695
Tue Oct 22 12:57:24 2019 [130230][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
Tue Oct 22 12:57:24 2019 [130230][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
Tue Oct 22 12:57:24 2019 [130230][1][INFO] Query Execution Time:0.00033307075500488
Tue Oct 22 12:57:24 2019 [130230][1][INFO] Tracker: retrieving 10 items
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] Hook called: Administration::after_ui_frame
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] Creating new instance of hook class hooks without parameters
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] SecuritySuite: Get SecuritySuite Enabled Modules: SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Oct 22 12:57:24 2019 [130230][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Oct 22 12:57:24 2019 [130230][1][INFO] Query Execution Time:0.00054812431335449
Tue Oct 22 12:57:24 2019 [130230][1][WARN] Undefined index: server_unique_key
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] Hook called: ::after_ui_footer
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] Hook called: ::server_round_trip
Tue Oct 22 12:57:24 2019 [130230][1][DEBUG] Calling MySQLi::disconnect()
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] current_language is: en_us
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Found cache backend SugarCacheMemcached
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Found cache backend SugarCacheMemcache
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Found cache backend SugarCacheFile
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Found cache backend SugarCacheAPC
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Found cache backend SugarCacheMemory
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Found cache backend SugarCachesMash
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Found cache backend SugarCacheWincache
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Found cache backend SugarCacheRedis
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Found cache backend SugarCacheZend
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Found language file: en_us.lang.php
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Found custom language file: en_us.lang.php
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = ‘Active’ and deleted = 0
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Query Execution Time:0.00026297569274902
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Query:SELECT category, name, value FROM config
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Query Execution Time:0.0002131462097168
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = ‘system’
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Query Execution Time:0.00013184547424316
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = ‘3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705’
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Query Execution Time:0.00014495849609375
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Hook called: ::after_entry_point
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Including module specific hook file for custom/modules
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Including Ext hook file for custom/application
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Hook called: ::after_session_start
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Unable to find SugarController:: EditView
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] We have an authenticated user id: 1
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Hook called: Users::before_retrieve
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Retrieve User : SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0
Tue Oct 22 12:57:25 2019 [130232][-none-][DEBUG] Limit Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 Start: 0 count: 1
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Oct 22 12:57:25 2019 [130232][-none-][INFO] Query Execution Time:0.00028514862060547
Tue Oct 22 12:57:25 2019 [130232][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
Tue Oct 22 12:57:25 2019 [130232][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Tue Oct 22 12:57:25 2019 [130232][1][INFO] Query Execution Time:0.00028800964355469
Tue Oct 22 12:57:25 2019 [130232][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
Tue Oct 22 12:57:25 2019 [130232][1][INFO] Query Execution Time:0.00019097328186035
Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Tue Oct 22 12:57:25 2019 [130232][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
Tue Oct 22 12:57:25 2019 [130232][1][INFO] Query Execution Time:0.00037097930908203
Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] Hook called: Users::after_retrieve
Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] FACTOR AUTH: User doesnt need factor auth Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] Current user is: kinadmin Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] Current user is: kinadmin Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] setting cookie ck_login_id_20 to 1 Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] setting cookie ck_login_language_20 to en_us Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] current_language is: en_us Tue Oct 22 12:57:25 2019 [130232][1][INFO] Found language file: en_us.lang.php Tue Oct 22 12:57:25 2019 [130232][1][INFO] Found custom language file: en_us.lang.php Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] Using Action View Map:edit Tue Oct 22 12:57:25 2019 [130232][1][WARN] CSS File Day/yui.css not found Tue Oct 22 12:57:25 2019 [130232][1][INFO] Query:SELECT parent_id, parent_type FROM favorites WHERE assigned_user_id = '1' AND deleted = 0 ORDER BY date_entered DESC Tue Oct 22 12:57:25 2019 [130232][1][INFO] Query Execution Time:0.000244140625 Tue Oct 22 12:57:25 2019 [130232][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 Tue Oct 22 12:57:25 2019 [130232][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 Tue Oct 22 12:57:25 2019 [130232][1][INFO] Query Execution Time:0.00033402442932129 Tue Oct 22 12:57:25 2019 [130232][1][INFO] Tracker: retrieving 10 items Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] Hook called: Configurator::after_ui_frame Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] Creating new instance of hook class hooks without parameters Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] Creating new instance of hook class AssignGroups without parameters Tue Oct 22 12:57:25 2019 [130232][1][WARN] Undefined index: server_unique_key Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] Hook called: ::after_ui_footer Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] Creating new instance of hook class AssignGroups without parameters Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] Hook called: ::server_round_trip Tue Oct 22 12:57:25 2019 [130232][1][DEBUG] Calling MySQLi::disconnect() Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] current_language is: en_us Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Found cache backend SugarCacheMemcached Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Found cache backend SugarCacheMemcache Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Found cache backend SugarCacheFile Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Found cache backend SugarCacheAPC Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Found cache backend SugarCacheMemory Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000 Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Found cache backend SugarCachesMash Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Found cache backend SugarCacheWincache Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Found cache backend SugarCacheRedis Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Found cache backend SugarCacheZend Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Found language file: en_us.lang.php Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Found custom language file: en_us.lang.php Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0 Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Query Execution Time:0.00023007392883301 Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Query:SELECT category, name, value FROM config Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Query Execution Time:0.00015497207641602 Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system' Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Query Execution Time:0.0001368522644043 Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705' Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Query Execution Time:0.00015711784362793 Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] current_language is: en_us Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Found cache backend SugarCacheMemcached Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Found cache backend SugarCacheMemcache Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Found cache backend SugarCacheFile Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Found cache backend SugarCacheAPC Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Found cache backend SugarCacheMemory Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000 Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Found cache backend SugarCachesMash Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Found cache backend SugarCacheWincache Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Found cache backend SugarCacheRedis Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Found cache backend SugarCacheZend Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Hook called: ::after_entry_point Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Including module specific hook file for custom/modules Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Including Ext hook file for custom/application Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Hook called: ::after_session_start Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Unable to find SugarController:: LogView Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] We have an authenticated user id: 1 Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Hook called: Users::before_retrieve Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Including module specific hook file for custom/modules/Users Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Retrieve User : SELECT users.* FROM users WHERE users.id = '1' AND users.deleted=0 Tue Oct 22 12:57:28 2019 [130238][-none-][DEBUG] Limit Query:SELECT users.* FROM users WHERE users.id = '1' AND users.deleted=0 Start: 0 count: 1 Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Query:SELECT users.* FROM users WHERE users.id = '1' AND users.deleted=0 LIMIT 0,1 Tue Oct 22 12:57:28 2019 [130238][-none-][INFO] Query Execution Time:0.00024700164794922 Tue Oct 22 12:57:28 2019 [130238][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 Tue Oct 22 12:57:28 2019 [130238][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC Tue Oct 22 12:57:28 2019 [130238][1][INFO] Query Execution Time:0.00017786026000977 Tue Oct 22 12:57:28 2019 [130238][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 Tue Oct 22 12:57:28 2019 [130238][1][INFO] Query Execution Time:0.00014495849609375 Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link). Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Found language file: en_us.lang.php Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Found custom language file: en_us.lang.php Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0 Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Query Execution Time:0.00014996528625488 Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Query:SELECT category, name, value FROM config Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Query Execution Time:0.00015401840209961 Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system' Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Query Execution Time:0.00011801719665527 Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705' Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Query Execution Time:0.00013995170593262 Tue Oct 22 12:57:28 2019 [130238][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 Tue Oct 22 12:57:28 2019 [130238][1][INFO] Query Execution Time:0.00029706954956055 Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] Hook called: Users::after_retrieve Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] FACTOR AUTH: ------------------------------------------------------------- Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH --------------------- Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] FACTOR AUTH: ------------------------------------------------------------- Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] FACTOR AUTH: User doesnt need factor auth
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] setting cookie ck_login_id_20 to 1
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] setting cookie ck_login_language_20 to en_us
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] current_language is: en_us
Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Hook called: ::after_entry_point
Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Including module specific hook file for custom/modules
Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Including Ext hook file for custom/application
Tue Oct 22 12:57:28 2019 [130238][1][INFO] Found language file: en_us.lang.php
Tue Oct 22 12:57:28 2019 [130238][1][INFO] Found custom language file: en_us.lang.php
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] Module:Configurator using file: LogView
Tue Oct 22 12:57:28 2019 [130238][1][DEPRECATED] Array
(
)

Tue Oct 22 12:57:28 2019 [130238][1][WARN] CSS File Day/yui.css not found
Tue Oct 22 12:57:28 2019 [130238][1][INFO] Query:SELECT parent_id, parent_type FROM favorites WHERE assigned_user_id = ‘1’ AND deleted = 0 ORDER BY date_entered DESC
Tue Oct 22 12:57:28 2019 [130238][1][INFO] Query Execution Time:0.00018715858459473
Tue Oct 22 12:57:28 2019 [130238][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
Tue Oct 22 12:57:28 2019 [130238][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
Tue Oct 22 12:57:28 2019 [130238][1][INFO] Query Execution Time:0.00030279159545898
Tue Oct 22 12:57:28 2019 [130238][1][INFO] Tracker: retrieving 10 items
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] Hook called: Configurator::after_ui_frame
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] Creating new instance of hook class hooks without parameters
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Tue Oct 22 12:57:28 2019 [130238][1][WARN] Undefined index: server_unique_key
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] Hook called: ::after_ui_footer
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] Hook called: ::server_round_trip
Tue Oct 22 12:57:28 2019 [130238][1][DEBUG] Calling MySQLi::disconnect()
Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Hook called: ::after_session_start
Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Unable to find SugarController:: get
Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] We have an authenticated user id: 1
Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Hook called: Users::before_retrieve
Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Retrieve User : SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0
Tue Oct 22 12:57:28 2019 [130237][-none-][DEBUG] Limit Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 Start: 0 count: 1
Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Oct 22 12:57:28 2019 [130237][-none-][INFO] Query Execution Time:0.00035500526428223
Tue Oct 22 12:57:28 2019 [130237][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
Tue Oct 22 12:57:28 2019 [130237][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Tue Oct 22 12:57:28 2019 [130237][1][INFO] Query Execution Time:0.00020718574523926
Tue Oct 22 12:57:28 2019 [130237][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
Tue Oct 22 12:57:28 2019 [130237][1][INFO] Query Execution Time:0.00016093254089355
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Tue Oct 22 12:57:28 2019 [130237][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
Tue Oct 22 12:57:28 2019 [130237][1][INFO] Query Execution Time:0.00034618377685547
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] Hook called: Users::after_retrieve
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] FACTOR AUTH: User does`nt need factor auth
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] setting cookie ck_login_id_20 to 1
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] setting cookie ck_login_language_20 to en_us
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] current_language is: en_us
Tue Oct 22 12:57:28 2019 [130237][1][INFO] Found language file: en_us.lang.php
Tue Oct 22 12:57:28 2019 [130237][1][INFO] Found custom language file: en_us.lang.php
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] Performing action: action_get MODULE: Alerts
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] get_full_list: order_by = ‘alerts.date_entered’ and where = ‘alerts.assigned_user_id = ‘1’ AND is_read != ‘1’’
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (modified_user_link).
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (created_by_link).
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (assigned_user_link).
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] process_order_by: (alerts.date_entered) does not have a vardef entry.
Tue Oct 22 12:57:28 2019 [130237][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
Tue Oct 22 12:57:28 2019 [130237][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
Tue Oct 22 12:57:28 2019 [130237][1][INFO] Query Execution Time:0.00036907196044922
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] process_full_list_query: result is mysqli_result Object
(
[current_field] => 0
[field_count] => 23
[lengths] =>
[num_rows] => 0
[type] => 0
)

Tue Oct 22 12:57:28 2019 [130237][1][DEPRECATED] Array
(
)

Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] Hook called: ::server_round_trip
Tue Oct 22 12:57:28 2019 [130237][1][DEBUG] Calling MySQLi::disconnect()
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] current_language is: en_us
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Found cache backend SugarCacheMemcached
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Found cache backend SugarCacheMemcache
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Found cache backend SugarCacheFile
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Found cache backend SugarCacheAPC
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Found cache backend SugarCacheMemory
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Found cache backend SugarCachesMash
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Found cache backend SugarCacheWincache
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Found cache backend SugarCacheRedis
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Found cache backend SugarCacheZend
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Found language file: en_us.lang.php
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Found custom language file: en_us.lang.php
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = ‘Active’ and deleted = 0
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Query Execution Time:0.00021505355834961
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Query:SELECT category, name, value FROM config
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Query Execution Time:0.00019288063049316
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = ‘system’
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Query Execution Time:0.00012302398681641
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = ‘3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705’
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Query Execution Time:0.00015091896057129
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Hook called: ::after_entry_point
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Including module specific hook file for custom/modules
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Including Ext hook file for custom/application
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Hook called: ::after_session_start
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Unable to find SugarController:: get
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] We have an authenticated user id: 1
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Hook called: Users::before_retrieve
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Retrieve User : SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0
Tue Oct 22 12:57:30 2019 [130241][-none-][DEBUG] Limit Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 Start: 0 count: 1
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Oct 22 12:57:30 2019 [130241][-none-][INFO] Query Execution Time:0.00028395652770996
Tue Oct 22 12:57:30 2019 [130241][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
Tue Oct 22 12:57:30 2019 [130241][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Tue Oct 22 12:57:30 2019 [130241][1][INFO] Query Execution Time:0.0002281665802002
Tue Oct 22 12:57:30 2019 [130241][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
Tue Oct 22 12:57:30 2019 [130241][1][INFO] Query Execution Time:0.00015592575073242
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Tue Oct 22 12:57:30 2019 [130241][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
Tue Oct 22 12:57:30 2019 [130241][1][INFO] Query Execution Time:0.00036787986755371
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] Hook called: Users::after_retrieve
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] FACTOR AUTH: User does`nt need factor auth
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] setting cookie ck_login_id_20 to 1
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] setting cookie ck_login_language_20 to en_us
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] current_language is: en_us
Tue Oct 22 12:57:30 2019 [130241][1][INFO] Found language file: en_us.lang.php
Tue Oct 22 12:57:30 2019 [130241][1][INFO] Found custom language file: en_us.lang.php
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] Performing action: action_get MODULE: Alerts
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] get_full_list: order_by = ‘alerts.date_entered’ and where = ‘alerts.assigned_user_id = ‘1’ AND is_read != ‘1’’
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (modified_user_link).
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (created_by_link).
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] SugarBean[Alert].load_relationships, Loading relationship (assigned_user_link).
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] process_order_by: (alerts.date_entered) does not have a vardef entry.
Tue Oct 22 12:57:30 2019 [130241][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
Tue Oct 22 12:57:30 2019 [130241][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
Tue Oct 22 12:57:30 2019 [130241][1][INFO] Query Execution Time:0.00029492378234863
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] process_full_list_query: result is mysqli_result Object
(
[current_field] => 0
[field_count] => 23
[lengths] =>
[num_rows] => 0
[type] => 0
)

Tue Oct 22 12:57:30 2019 [130241][1][DEPRECATED] Array
(
)

Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] Hook called: ::server_round_trip
Tue Oct 22 12:57:30 2019 [130241][1][DEBUG] Calling MySQLi::disconnect()
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] current_language is: en_us
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Found cache backend SugarCacheMemcached
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Found cache backend SugarCacheMemcache
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Found cache backend SugarCacheFile
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Found cache backend SugarCacheAPC
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Found cache backend SugarCacheMemory
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Found cache backend SugarCachesMash
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Found cache backend SugarCacheWincache
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Found cache backend SugarCacheRedis
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Found cache backend SugarCacheZend
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Found language file: en_us.lang.php
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Found custom language file: en_us.lang.php
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = ‘Active’ and deleted = 0
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Query Execution Time:0.00021505355834961
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Query:SELECT category, name, value FROM config
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Query Execution Time:0.00017690658569336
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = ‘system’
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Query Execution Time:0.00012111663818359
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = ‘3ca9689a-9b0d-1cc2-bc7e-5d42d0d49705’
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Query Execution Time:0.00014281272888184
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Hook called: ::after_entry_point
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Including module specific hook file for custom/modules
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Including Ext hook file for custom/application
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Hook called: ::after_session_start
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Unable to find SugarController:: LogView
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] We have an authenticated user id: 1
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Hook called: Users::before_retrieve
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Retrieve User : SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0
Tue Oct 22 12:57:32 2019 [130242][-none-][DEBUG] Limit Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 Start: 0 count: 1
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Query:SELECT users.* FROM users WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Oct 22 12:57:32 2019 [130242][-none-][INFO] Query Execution Time:0.00024795532226562
Tue Oct 22 12:57:32 2019 [130242][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
Tue Oct 22 12:57:32 2019 [130242][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Tue Oct 22 12:57:32 2019 [130242][1][INFO] Query Execution Time:0.00024819374084473
Tue Oct 22 12:57:32 2019 [130242][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
Tue Oct 22 12:57:32 2019 [130242][1][INFO] Query Execution Time:0.00017094612121582
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Tue Oct 22 12:57:32 2019 [130242][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
Tue Oct 22 12:57:32 2019 [130242][1][INFO] Query Execution Time:0.00034904479980469
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] Hook called: Users::after_retrieve
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] FACTOR AUTH: User does`nt need factor auth
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] Current user is: kinadmin
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] setting cookie ck_login_id_20 to 1
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] setting cookie ck_login_language_20 to en_us
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] current_language is: en_us
Tue Oct 22 12:57:32 2019 [130242][1][INFO] Found language file: en_us.lang.php
Tue Oct 22 12:57:32 2019 [130242][1][INFO] Found custom language file: en_us.lang.php
Tue Oct 22 12:57:32 2019 [130242][1][DEBUG] Module:Configurator using file: LogView
Tue Oct 22 12:57:32 2019 [130242][1][DEPRECATED] Array
(
)

Tue Oct 22 12:57:32 2019 [130242][1][WARN] CSS File Day/yui.css not found
Tue Oct 22 12:57:32 2019 [130242][1][INFO] Query:SELECT parent_id, parent_type FROM favorites WHERE assigned_user_id = ‘1’ AND deleted = 0 ORDER BY date_entered DESC
Tue Oct 22 12:57:32 2019 [130242][1][INFO] Query Execution Time:0.00020480155944824
Tue Oct 22 12:57:32 2019 [130242][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
Tue Oct 22 12:57:32 2019 [130242][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
Tue Oct 22 12:57:32 2019 [130242][1][INFO] Query Execution Time:0.00037813186645508
Tue Oct 22 12:57:32 2019 [130242][1][INFO] Tracker: retrieving 10 items

pgr · 22 October 2019 13:14

What I don’t understand about your logs:

why I don’t see any entries with “PHPMailer Send Function”? Isn’t that line logging anything? Why?
why I only see two entries with “smtp send”, with the connection closing. There should be lines before that, with the connection initiating, and with some other dialogue with the server.

It’s hard to help further without this information, can you try discovering why this is happening?