Thread Details
  • State Not Answered
  • Replies 14 replies
  • Subscribers 354 subscribers
  • Views 3155 views
  • Users 0 members are here
Forum Actions
Related

Inbound Email Not Working Getting Logs Error -could not get an IMAP connection resource for/ failed in CRON run

Manish kumar

Inbound Email Not Working Getting Logs Errors

We are Suddenly Failed to Synced Inbox From Email to Sugarcrm Auto Synced We are Not Getting To received or synced emails from Other Email Box.

Please Help And Suggest What is The issue.


Sun Nov 6 04:32:02 2022 [26170][1][FATAL] SCHEDULERS: could not get an IMAP connection resource for ID [ 9440dd14-d617-11ea-ac13-022fbf6a8230 ]. Skipping mailbox [ dom@acx.in ].
Sun Nov 6 04:32:02 2022 [26170][1][FATAL] Job f5bfe000-5d8b-11ed-a6d9-022fbf6a8230 (Check Inbound Mailboxes) failed in CRON run

Parents
  • 0

    Hi ,

    I have some additional questions to better understand why you may be receiving the error and identify potential ways to troubleshoot:

    • What type of mail account is this? (Outlook 365, Google Workspace, self-hosted Exchange, etc.)
    • Where is your Sugar instance hosted? (SugarCloud, third party cloud provider, self-hosted) If it is not SugarCloud, do you have access to the command line of the server hosting Sugar?
    • When was mail last successfully retrieved from the mailbox?
    • Do you have any other services (inboxes or SMTP setups) configured with this mail server? If so, are they all experiencing problems?

    Co-Founder | SugarCRM's 2024 Global Outfitters Partner of the Year

  • 0 in reply to Chris Raffle

    Hi Chris,

    We have exactly the same problem as Manish describes. The error message is also the same.

    "Mon Nov  6 17:30:06 2023 [14464][1][FATAL] SCHEDULERS: could not get an IMAP connection resource for ID [ 82ec300e-bca7-11e7-94a4-005056885384 ]. Skipping mailbox [ Case compose email cc ]."

    We upgraded from V11.0.3 to V13.0.0 a couple months ago. Since then the problem occurs. But nobody was really bothered, until a few days ago.

    We connect to an "Other" Email Provider. In our case this is a self hosted Exchange solution. It is an IMAP connection via SSL. The server address and port are entered correctly, and the settings can be successfully verified with "Test Settings".

    Do you have any idea what this could be?

    Thank you for giving this a quick skim.

    Rene

  • 0 in reply to Rene Ryhner

    Hi  ,

    Based on your description, I am assuming you are hosting Sugar on servers you have access to. If that is an accurate assumption, I recommend first setting the logging level of Sugar to 'Debug' which can be found under Admin > System Settings. Leave it in that logging level until the inbound email scheduler attempts to run again. Once the scheduler runs, set the logging level back to 'Fatal' to prevent unnecessary logs from generating. Inspect the sugarcrm.log file found in the root directory of your Sugar instance and search for the fatal message you cite in your post. If you scan through the content before that fatal message, you should see some more verbose output around the attempt to connect to the mailbox. Please remove any sensitive information related to that connection attempt and share the log output. I'll see if I can help further once seeing that content.

    Please also share the operating system of the server that hosts Sugar.

    Thanks!

    Chris

    Co-Founder | SugarCRM's 2024 Global Outfitters Partner of the Year

  • 0 in reply to Chris Raffle

    Hi Chris,

    Thank you for your quick response, Our Sugar runs on Windows Server 2019. I've attached an extract of the sugarcrm.log. At first glance, I can't find anything more meaningful, but maybe this will tell you something more.

    Thank you for taking the time to look into this. 

    Best regards
    Rene


    Fullscreen sugar.log Download 
    Tue Nov  7 08:24:03 2023 [8976][1][INFO] ----->Scheduler fired job of type pollMonitoredInboxes()
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] VardefManager::loadVardef called for module: InboundEmail
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Loading Preferences DB 1
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT contents FROM user_preferences WHERE assigned_user_id = ? AND category = ? AND deleted = 0\r\nParams: ["1","Emails"]
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] VardefManager::loadVardef called for module: Emails
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT af.name, af.aclaccess FROM acl_fields af INNER JOIN acl_roles_users aru ON aru.user_id = ? AND aru.deleted=0 INNER JOIN acl_roles ar ON aru.role_id = ar.id AND ar.id = af.role_id AND ar.deleted = 0 WHERE af.deleted = 0 AND af.category = ?\r\nParams: ["1","Emails"]
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT id, name FROM inbound_email WHERE is_personal = 0 AND deleted=0 AND status='Active' AND mailbox_type != 'bounce'
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query Execution Time: 0.0050919055938721
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Just got Result from get all Inbounds of Inbound Emails
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] In while loop of Inbound Emails
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: InboundEmail::before_retrieve
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Retrieve InboundEmail
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] SugarBean[InboundEmail].load_relationships, Loading link (team_link).
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT a.* FROM (SELECT inbound_email.id, inbound_email.eapm_id, inbound_email.authorized_account, inbound_email.auth_type, inbound_email.email_provider, inbound_email.deleted, inbound_email.date_entered, inbound_email.date_modified, inbound_email.modified_user_id, inbound_email.created_by, inbound_email.name, inbound_email.status, inbound_email.server_url, inbound_email.email_user, inbound_email.email_password, inbound_email.port, inbound_email.service, inbound_email.mailbox, inbound_email.delete_seen, inbound_email.mailbox_type, inbound_email.template_id, inbound_email.stored_options, inbound_email.group_id, inbound_email.is_personal, inbound_email.groupfolder_id, inbound_email.team_id, inbound_email.team_set_id, inbound_email.acl_team_set_id, teams_tn.name tn_name, teams_tn.name_2 tn_name_2 FROM inbound_email LEFT JOIN teams teams_tn ON (inbound_email.team_id = teams_tn.id) AND (teams_tn.deleted = ?) WHERE (inbound_email.id = ?) AND (inbound_email.deleted = ?)) a WHERE ROWNUM <= 1\r\nParams: [0,"82ec300e-bca7-11e7-94a4-005056885384",0]\r\nTypes: [5,2,5]
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::before_fetch_query
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT teams.created_by, teams.id FROM teams WHERE (teams.id = ?) AND (teams.deleted = ?)\r\nParams: ["1",0]\r\nTypes: [2,5]
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::process_record
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::after_fetch_query
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::before_fetch_query
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT teams.name, teams.created_by, teams.id FROM teams WHERE (teams.id = ?) AND (teams.deleted = ?)\r\nParams: ["1",0]\r\nTypes: [2,5]
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::process_record
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::after_fetch_query
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: InboundEmail::after_retrieve
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Trying to connect to mailserver for [ Case compose email cc ]
Tue Nov  7 08:24:04 2023 [8976][1][FATAL] SCHEDULERS: could not get an IMAP connection resource for ID [ 82ec300e-bca7-11e7-94a4-005056885384 ]. Skipping mailbox [ Case compose email cc ].
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"id":"9c0ac26e-70dd-11e7-a0a1-000c2957f404","_module":"Schedulers","_type":"cron-job"}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Resolving job a03ff510-7d3e-11ee-b37b-005056884f9c as success: 
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Entered operation status: updating_relationships
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Left operation status: updating_relationships
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Hook called: SchedulersJobs::before_save
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: UPDATE job_queue SET name = ?, date_modified = to_date(?, 'YYYY-MM-DD HH24:MI:SS'), scheduler_id = ?, execute_time = to_date(?, 'YYYY-MM-DD HH24:MI:SS'), status = ?, resolution = ?, message = ?, target = ?, data = ?, requeue = ?, retry_count = ?, failure_count = ?, job_delay = ?, client = ?, percent_complete = ?, job_group = ?, module = ?, fallible = ?, rerun = ?, interface = ?, assigned_user_id = ? WHERE (id = ?) AND (deleted = ?)\r\nParams: ["Check Inbound Mailboxes","2023-11-07 07:24:01","9c0ac26e-70dd-11e7-a0a1-000c2957f404","2023-11-07 07:24:01","done","success","","function::pollMonitoredInboxes","",0,null,null,0,"CRONf8562ddb772b01f68b2d7b62a48c74bf:8976",null,null,null,0,0,1,"1","a03ff510-7d3e-11ee-b37b-005056884f9c",0]\r\nTypes: [2,2,2,2,2,2,2,2,2,5,1,1,1,2,1,2,2,5,5,5,2,2,5]
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Updating records related to SchedulersJobs a03ff510-7d3e-11ee-b37b-005056884f9c
Tue Nov  7 08:24:04 2023 [8976][1][INFO] tableExists: time_aware_schedules
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: SELECT TABLE_NAME\nFROM ALL_TABLES\nWHERE OWNER = ?\n    AND TABLE_NAME = ?\r\nParams: ["CRM","TIME_AWARE_SCHEDULES"]
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Entered operation status: saving_related
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Left operation status: saving_related
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: SELECT data FROM erased_fields WHERE bean_id = ? AND table_name = ?\r\nParams: ["a03ff510-7d3e-11ee-b37b-005056884f9c","job_queue"]
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Hook called: SchedulersJobs::after_save
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"ActivityQueueManager","method":"eventDispatcher","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class 'ActivityQueueManager' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"ActivityQueueManager","method":"eventDispatcher","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SearchEngine\\HookHandler","method":"indexBean","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\SearchEngine\HookHandler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SearchEngine\\HookHandler","method":"indexBean","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\Maps\\HookHandler","method":"geocode","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\Maps\HookHandler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\Maps\\HookHandler","method":"geocode","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SugarConnect\\LogicHooks\\Handler","method":"publish","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\SugarConnect\LogicHooks\Handler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SugarConnect\\LogicHooks\\Handler","method":"publish","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\CustomerJourney\\LogicHooks\\JourneyParentHooksHelper","method":"afterSave","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\CustomerJourney\LogicHooks\JourneyParentHooksHelper' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\CustomerJourney\\LogicHooks\\JourneyParentHooksHelper","method":"afterSave","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\PubSub\\Module\\Event\\Publisher","method":"handleEvent","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\PubSub\Module\Event\Publisher' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\PubSub\\Module\\Event\\Publisher","method":"handleEvent","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"PMSELogicHook","method":"after_save","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class 'PMSELogicHook' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"PMSELogicHook","method":"after_save","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: UPDATE schedulers SET last_run=to_date('2023-11-07 07:24:01', 'YYYY-MM-DD HH24:MI:SS') WHERE id='9c0ac26e-70dd-11e7-a0a1-000c2957f404'
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query Execution Time: 0.0032110214233398
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Get One: |SELECT id FROM job_queue WHERE execute_time <= to_date('2023-11-07 07:24:01', 'YYYY-MM-DD HH24:MI:SS') AND status = 'queued' AND deleted = 0 ORDER BY execute_time ASC|
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Limit Query:SELECT id FROM job_queue WHERE execute_time <= to_date('2023-11-07 07:24:01', 'YYYY-MM-DD HH24:MI:SS') AND status = 'queued' AND deleted = 0 ORDER BY execute_time ASC Start: 0 count: 1
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: SELECT /*+ FIRST_ROWS(1) */ * FROM (SELECT id FROM job_queue WHERE execute_time <= to_date('2023-11-07 07:24:01', 'YYYY-MM-DD HH24:MI:SS') AND status = 'queued' AND deleted = 0 ORDER BY execute_time ASC) MSI WHERE ROWNUM <= 1
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query Execution Time: 0.00037097930908203
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: UPDATE job_queue SET status='running', date_modified=to_date('2023-11-07 07:24:01', 'YYYY-MM-DD HH24:MI:SS'), client='CRONf8562ddb772b01f68b2d7b62a48c74bf:8976' WHERE id='a0444bba-7d3e-11ee-be11-005056884f9c' AND status='queued'
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query Execution Time: 0.0037059783935547
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Entered operation status: updating_relationships
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Left operation status: updating_relationships
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Hook called: SchedulersJobs::before_save
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: UPDATE job_queue SET name = ?, date_modified = to_date(?, 'YYYY-MM-DD HH24:MI:SS'), scheduler_id = ?, execute_time = to_date(?, 'YYYY-MM-DD HH24:MI:SS'), status = ?, resolution = ?, message = ?, target = ?, data = ?, requeue = ?, retry_count = ?, failure_count = ?, job_delay = ?, client = ?, percent_complete = ?, job_group = ?, module = ?, fallible = ?, rerun = ?, interface = ?, assigned_user_id = ? WHERE (id = ?) AND (deleted = ?)\r\nParams: ["Update tracker_sessions Table","2023-11-07 07:24:01","9c0e4ccc-70dd-11e7-b7d6-000c2957f404","2023-11-07 07:24:01","running","queued","","function::updateTrackerSessions","",0,null,null,0,"CRONf8562ddb772b01f68b2d7b62a48c74bf:8976",null,null,null,0,0,1,"1","a0444bba-7d3e-11ee-be11-005056884f9c",0]\r\nTypes: [2,2,2,2,2,2,2,2,2,5,1,1,1,2,1,2,2,5,5,5,2,2,5]
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Updating records related to SchedulersJobs a0444bba-7d3e-11ee-be11-005056884f9c
Tue Nov  7 08:24:04 2023 [8976][1][INFO] tableExists: time_aware_schedules
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: SELECT TABLE_NAME\nFROM ALL_TABLES\nWHERE OWNER = ?\n    AND TABLE_NAME = ?\r\nParams: ["CRM","TIME_AWARE_SCHEDULES"]
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Entered operation status: saving_related
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Left operation status: saving_related
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: SELECT data FROM erased_fields WHERE bean_id = ? AND table_name = ?\r\nParams: ["a0444bba-7d3e-11ee-be11-005056884f9c","job_queue"]
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Hook called: SchedulersJobs::after_save
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"ActivityQueueManager","method":"eventDispatcher","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class 'ActivityQueueManager' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"ActivityQueueManager","method":"eventDispatcher","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SearchEngine\\HookHandler","method":"indexBean","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\SearchEngine\HookHandler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SearchEngine\\HookHandler","method":"indexBean","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\Maps\\HookHandler","method":"geocode","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\Maps\HookHandler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\Maps\\HookHandler","method":"geocode","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SugarConnect\\LogicHooks\\Handler","method":"publish","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\SugarConnect\LogicHooks\Handler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SugarConnect\\LogicHooks\\Handler","method":"publish","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\CustomerJourney\\LogicHooks\\JourneyParentHooksHelper","method":"afterSave","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\CustomerJourney\LogicHooks\JourneyParentHooksHelper' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\CustomerJourney\\LogicHooks\\JourneyParentHooksHelper","method":"afterSave","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\PubSub\\Module\\Event\\Publisher","method":"handleEvent","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\PubSub\Module\Event\Publisher' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\PubSub\\Module\\Event\\Publisher","method":"handleEvent","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"PMSELogicHook","method":"after_save","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class 'PMSELogicHook' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"PMSELogicHook","method":"after_save","label":null}

Reply
  • 0 in reply to Chris Raffle

    Hi Chris,

    Thank you for your quick response, Our Sugar runs on Windows Server 2019. I've attached an extract of the sugarcrm.log. At first glance, I can't find anything more meaningful, but maybe this will tell you something more.

    Thank you for taking the time to look into this. 

    Best regards
    Rene


    Fullscreen sugar.log Download 
    Tue Nov  7 08:24:03 2023 [8976][1][INFO] ----->Scheduler fired job of type pollMonitoredInboxes()
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] VardefManager::loadVardef called for module: InboundEmail
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Loading Preferences DB 1
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT contents FROM user_preferences WHERE assigned_user_id = ? AND category = ? AND deleted = 0\r\nParams: ["1","Emails"]
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] VardefManager::loadVardef called for module: Emails
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT af.name, af.aclaccess FROM acl_fields af INNER JOIN acl_roles_users aru ON aru.user_id = ? AND aru.deleted=0 INNER JOIN acl_roles ar ON aru.role_id = ar.id AND ar.id = af.role_id AND ar.deleted = 0 WHERE af.deleted = 0 AND af.category = ?\r\nParams: ["1","Emails"]
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT id, name FROM inbound_email WHERE is_personal = 0 AND deleted=0 AND status='Active' AND mailbox_type != 'bounce'
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query Execution Time: 0.0050919055938721
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Just got Result from get all Inbounds of Inbound Emails
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] In while loop of Inbound Emails
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: InboundEmail::before_retrieve
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Retrieve InboundEmail
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] SugarBean[InboundEmail].load_relationships, Loading link (team_link).
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT a.* FROM (SELECT inbound_email.id, inbound_email.eapm_id, inbound_email.authorized_account, inbound_email.auth_type, inbound_email.email_provider, inbound_email.deleted, inbound_email.date_entered, inbound_email.date_modified, inbound_email.modified_user_id, inbound_email.created_by, inbound_email.name, inbound_email.status, inbound_email.server_url, inbound_email.email_user, inbound_email.email_password, inbound_email.port, inbound_email.service, inbound_email.mailbox, inbound_email.delete_seen, inbound_email.mailbox_type, inbound_email.template_id, inbound_email.stored_options, inbound_email.group_id, inbound_email.is_personal, inbound_email.groupfolder_id, inbound_email.team_id, inbound_email.team_set_id, inbound_email.acl_team_set_id, teams_tn.name tn_name, teams_tn.name_2 tn_name_2 FROM inbound_email LEFT JOIN teams teams_tn ON (inbound_email.team_id = teams_tn.id) AND (teams_tn.deleted = ?) WHERE (inbound_email.id = ?) AND (inbound_email.deleted = ?)) a WHERE ROWNUM <= 1\r\nParams: [0,"82ec300e-bca7-11e7-94a4-005056885384",0]\r\nTypes: [5,2,5]
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::before_fetch_query
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT teams.created_by, teams.id FROM teams WHERE (teams.id = ?) AND (teams.deleted = ?)\r\nParams: ["1",0]\r\nTypes: [2,5]
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::process_record
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::after_fetch_query
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::before_fetch_query
Tue Nov  7 08:24:03 2023 [8976][1][INFO] Query: SELECT teams.name, teams.created_by, teams.id FROM teams WHERE (teams.id = ?) AND (teams.deleted = ?)\r\nParams: ["1",0]\r\nTypes: [2,5]
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::process_record
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: Teams::after_fetch_query
Tue Nov  7 08:24:03 2023 [8976][1][DEBUG] Hook called: InboundEmail::after_retrieve
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Trying to connect to mailserver for [ Case compose email cc ]
Tue Nov  7 08:24:04 2023 [8976][1][FATAL] SCHEDULERS: could not get an IMAP connection resource for ID [ 82ec300e-bca7-11e7-94a4-005056885384 ]. Skipping mailbox [ Case compose email cc ].
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"id":"9c0ac26e-70dd-11e7-a0a1-000c2957f404","_module":"Schedulers","_type":"cron-job"}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Resolving job a03ff510-7d3e-11ee-b37b-005056884f9c as success: 
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Entered operation status: updating_relationships
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Left operation status: updating_relationships
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Hook called: SchedulersJobs::before_save
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: UPDATE job_queue SET name = ?, date_modified = to_date(?, 'YYYY-MM-DD HH24:MI:SS'), scheduler_id = ?, execute_time = to_date(?, 'YYYY-MM-DD HH24:MI:SS'), status = ?, resolution = ?, message = ?, target = ?, data = ?, requeue = ?, retry_count = ?, failure_count = ?, job_delay = ?, client = ?, percent_complete = ?, job_group = ?, module = ?, fallible = ?, rerun = ?, interface = ?, assigned_user_id = ? WHERE (id = ?) AND (deleted = ?)\r\nParams: ["Check Inbound Mailboxes","2023-11-07 07:24:01","9c0ac26e-70dd-11e7-a0a1-000c2957f404","2023-11-07 07:24:01","done","success","","function::pollMonitoredInboxes","",0,null,null,0,"CRONf8562ddb772b01f68b2d7b62a48c74bf:8976",null,null,null,0,0,1,"1","a03ff510-7d3e-11ee-b37b-005056884f9c",0]\r\nTypes: [2,2,2,2,2,2,2,2,2,5,1,1,1,2,1,2,2,5,5,5,2,2,5]
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Updating records related to SchedulersJobs a03ff510-7d3e-11ee-b37b-005056884f9c
Tue Nov  7 08:24:04 2023 [8976][1][INFO] tableExists: time_aware_schedules
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: SELECT TABLE_NAME\nFROM ALL_TABLES\nWHERE OWNER = ?\n    AND TABLE_NAME = ?\r\nParams: ["CRM","TIME_AWARE_SCHEDULES"]
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Entered operation status: saving_related
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Left operation status: saving_related
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: SELECT data FROM erased_fields WHERE bean_id = ? AND table_name = ?\r\nParams: ["a03ff510-7d3e-11ee-b37b-005056884f9c","job_queue"]
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Hook called: SchedulersJobs::after_save
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"ActivityQueueManager","method":"eventDispatcher","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class 'ActivityQueueManager' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"ActivityQueueManager","method":"eventDispatcher","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SearchEngine\\HookHandler","method":"indexBean","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\SearchEngine\HookHandler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SearchEngine\\HookHandler","method":"indexBean","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\Maps\\HookHandler","method":"geocode","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\Maps\HookHandler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\Maps\\HookHandler","method":"geocode","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SugarConnect\\LogicHooks\\Handler","method":"publish","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\SugarConnect\LogicHooks\Handler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SugarConnect\\LogicHooks\\Handler","method":"publish","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\CustomerJourney\\LogicHooks\\JourneyParentHooksHelper","method":"afterSave","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\CustomerJourney\LogicHooks\JourneyParentHooksHelper' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\CustomerJourney\\LogicHooks\\JourneyParentHooksHelper","method":"afterSave","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\PubSub\\Module\\Event\\Publisher","method":"handleEvent","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\PubSub\Module\Event\Publisher' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\PubSub\\Module\\Event\\Publisher","method":"handleEvent","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"PMSELogicHook","method":"after_save","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class 'PMSELogicHook' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"PMSELogicHook","method":"after_save","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: UPDATE schedulers SET last_run=to_date('2023-11-07 07:24:01', 'YYYY-MM-DD HH24:MI:SS') WHERE id='9c0ac26e-70dd-11e7-a0a1-000c2957f404'
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query Execution Time: 0.0032110214233398
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Get One: |SELECT id FROM job_queue WHERE execute_time <= to_date('2023-11-07 07:24:01', 'YYYY-MM-DD HH24:MI:SS') AND status = 'queued' AND deleted = 0 ORDER BY execute_time ASC|
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Limit Query:SELECT id FROM job_queue WHERE execute_time <= to_date('2023-11-07 07:24:01', 'YYYY-MM-DD HH24:MI:SS') AND status = 'queued' AND deleted = 0 ORDER BY execute_time ASC Start: 0 count: 1
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: SELECT /*+ FIRST_ROWS(1) */ * FROM (SELECT id FROM job_queue WHERE execute_time <= to_date('2023-11-07 07:24:01', 'YYYY-MM-DD HH24:MI:SS') AND status = 'queued' AND deleted = 0 ORDER BY execute_time ASC) MSI WHERE ROWNUM <= 1
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query Execution Time: 0.00037097930908203
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: UPDATE job_queue SET status='running', date_modified=to_date('2023-11-07 07:24:01', 'YYYY-MM-DD HH24:MI:SS'), client='CRONf8562ddb772b01f68b2d7b62a48c74bf:8976' WHERE id='a0444bba-7d3e-11ee-be11-005056884f9c' AND status='queued'
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query Execution Time: 0.0037059783935547
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Entered operation status: updating_relationships
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Left operation status: updating_relationships
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Hook called: SchedulersJobs::before_save
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: UPDATE job_queue SET name = ?, date_modified = to_date(?, 'YYYY-MM-DD HH24:MI:SS'), scheduler_id = ?, execute_time = to_date(?, 'YYYY-MM-DD HH24:MI:SS'), status = ?, resolution = ?, message = ?, target = ?, data = ?, requeue = ?, retry_count = ?, failure_count = ?, job_delay = ?, client = ?, percent_complete = ?, job_group = ?, module = ?, fallible = ?, rerun = ?, interface = ?, assigned_user_id = ? WHERE (id = ?) AND (deleted = ?)\r\nParams: ["Update tracker_sessions Table","2023-11-07 07:24:01","9c0e4ccc-70dd-11e7-b7d6-000c2957f404","2023-11-07 07:24:01","running","queued","","function::updateTrackerSessions","",0,null,null,0,"CRONf8562ddb772b01f68b2d7b62a48c74bf:8976",null,null,null,0,0,1,"1","a0444bba-7d3e-11ee-be11-005056884f9c",0]\r\nTypes: [2,2,2,2,2,2,2,2,2,5,1,1,1,2,1,2,2,5,5,5,2,2,5]
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Updating records related to SchedulersJobs a0444bba-7d3e-11ee-be11-005056884f9c
Tue Nov  7 08:24:04 2023 [8976][1][INFO] tableExists: time_aware_schedules
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: SELECT TABLE_NAME\nFROM ALL_TABLES\nWHERE OWNER = ?\n    AND TABLE_NAME = ?\r\nParams: ["CRM","TIME_AWARE_SCHEDULES"]
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Entered operation status: saving_related
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Left operation status: saving_related
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Query: SELECT data FROM erased_fields WHERE bean_id = ? AND table_name = ?\r\nParams: ["a0444bba-7d3e-11ee-be11-005056884f9c","job_queue"]
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Hook called: SchedulersJobs::after_save
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"ActivityQueueManager","method":"eventDispatcher","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class 'ActivityQueueManager' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"ActivityQueueManager","method":"eventDispatcher","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SearchEngine\\HookHandler","method":"indexBean","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\SearchEngine\HookHandler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SearchEngine\\HookHandler","method":"indexBean","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\Maps\\HookHandler","method":"geocode","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\Maps\HookHandler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\Maps\\HookHandler","method":"geocode","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SugarConnect\\LogicHooks\\Handler","method":"publish","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\SugarConnect\LogicHooks\Handler' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\SugarConnect\\LogicHooks\\Handler","method":"publish","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\CustomerJourney\\LogicHooks\\JourneyParentHooksHelper","method":"afterSave","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\CustomerJourney\LogicHooks\JourneyParentHooksHelper' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\CustomerJourney\\LogicHooks\\JourneyParentHooksHelper","method":"afterSave","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\PubSub\\Module\\Event\\Publisher","method":"handleEvent","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class '\Sugarcrm\Sugarcrm\PubSub\Module\Event\Publisher' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"\\Sugarcrm\\Sugarcrm\\PubSub\\Module\\Event\\Publisher","method":"handleEvent","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject activated: {"_type":"logic-hook","class":"PMSELogicHook","method":"after_save","label":null}
Tue Nov  7 08:24:04 2023 [8976][1][DEBUG] Creating new instance of hook class 'PMSELogicHook' without parameters
Tue Nov  7 08:24:04 2023 [8976][1][INFO] Subject deactivated: {"_type":"logic-hook","class":"PMSELogicHook","method":"after_save","label":null}

Children
  • 0 in reply to Rene Ryhner

    Hi  ,

    You are correct, there is nothing substantial there. Please set the debug logging back to 'Debug' and then do the test connection for the mailbox. Once that is complete, set the logging level back to 'Fatal'. 

    In the log, you should find the string 'STARTING FINDOPTIMUMS LOOP'. Please provide all the content from that line (minus any sensitive info) until you reach the line containing the string 'end FINDOPTIMUMS LOOP'. This should identify how it is able to successfully connect to your mail server.

    Assuming the test settings attempt is successful, you will want to compare those findings with what is being stored for the mailbox in the database by running the following query:

    SELECT 
    name, 
    auth_type, 
    server_url, 
    port, 
    service, 
    mailbox, 
    mailbox_type, 
    stored_options 
FROM 
    inbound_email 
WHERE 
    id = '82ec300e-bca7-11e7-94a4-005056885384';

    It's possible Sugar is storing different options for the mailbox than what is being found as a successful connection when doing Test Settings.

    One additional thing to consider is how you are calling cron.php from your batch job. Is the batch command citing a different PHP build than the build used by your web server? Using the 'Test Settings' button will leverage your web server PHP build which could explain why that is successful but the scheduled job is failing if it is citing an older PHP build that may not be compatible with Sugar 13.

    Hopefully one of these help get you toward a resolution!

    Chris

    Co-Founder | SugarCRM's 2024 Global Outfitters Partner of the Year