Suitecrm: 7.11.15/7.10.27 [FATAL] Cannot find bean file for module: ____

[pgorod]

Issue

Since the latest upgrades the logs have started to get many spam FATAL messages:

Fri Jun 26 00:00:03 2020 [27134][1][FATAL] Cannot find bean file for module: 
Fri Jun 26 00:00:03 2020 [27134][1][FATAL] Cannot find bean file for module: Connectors
Fri Jun 26 00:00:03 2020 [27134][1][FATAL] Cannot find bean file for module: Connectors
Fri Jun 26 00:00:03 2020 [27134][1][FATAL] Cannot find bean file for module: CustomFields
Fri Jun 26 00:00:03 2020 [27134][1][FATAL] Cannot find bean file for module: CustomFields
Fri Jun 26 00:00:03 2020 [27134][1][FATAL] Cannot find bean file for module: Versions
Fri Jun 26 00:00:03 2020 [27134][1][FATAL] Cannot find bean file for module: Versions

Sample call stack with empty "module name":

Thu Jun 25 16:06:34 2020 [4953][1][FATAL] Cannot find bean file for module: 
#0 /data/BeanFactory.php(394):  LoggerManager->__call(
     method: 'fatal', 
     message: Array (
      [0] => 'Cannot find bean file for module: ')
#1 /data/BeanFactory.php(113):  BeanFactory::loadBeanFile(     module: '')
#2 /custom/modules/Emails/controller.php(28):  BeanFactory::getBean(
     module: '', 
     id: '')
#3 /include/MVC/Controller/SugarController.php(541):  CustomEmailsController->action_send()
#4 /include/MVC/Controller/SugarController.php(507):  SugarController->do_action()
#5 /include/MVC/Controller/SugarController.php(476):  SugarController->handle_action()
#6 /include/MVC/Controller/SugarController.php(379):  SugarController->process()
#7 /include/MVC/SugarApplication.php(113):  SugarController->execute()
#8 /index.php(52):  SugarApplication->execute()

Sample longer call stack with "module name" present:

Fri Jun 26 15:32:20 2020 [5256][1][FATAL] Cannot find bean file for module: Connectors
#0 /data/BeanFactory.php(394):  LoggerManager->__call(
     method: 'fatal', 
     message: Array (
      [0] => 'Cannot find bean file for module: Connectors')
#1 /data/BeanFactory.php(113):  BeanFactory::loadBeanFile(     module: 'Connectors')
#2 /data/BeanFactory.php(218):  BeanFactory::getBean(     module: 'Connectors')
#3 /include/SugarObjects/VardefManager.php(276):  BeanFactory::newBean(     module: 'Connectors')
#4 /include/SugarObjects/VardefManager.php(444):  VardefManager::refreshVardefs(
     module: 'Connectors', 
     object: 'Connectors', 
     additional_search_paths: , 
     cacheCustom: 1, 
     params: Array (
      [ignore_rel_calc_fields] => 1)
#5 /data/Relationships/RelationshipFactory.php(190):  VardefManager::loadVardef(
     module: 'Connectors', 
     object: 'Connectors', 
     refresh: , 
     params: Array (
      [ignore_rel_calc_fields] => 1)
#6 /data/Relationships/RelationshipFactory.php(170):  SugarRelationshipFactory->buildRelationshipCache()
#7 /data/Relationships/RelationshipFactory.php(64):  SugarRelationshipFactory->loadRelationships()
#8 /data/Relationships/RelationshipFactory.php(75):  SugarRelationshipFactory->__construct()
#9 /data/Link2.php(127):  SugarRelationshipFactory::getInstance()
#10 /data/SugarBean.php(1991):  Link2->__construct(
     linkName: 'reports_to_link', 
     bean: User Object (
      [name] => 'Administrator'
      [full_name] => 'Administrator'
      [id] => '1'
      [user_name] => 'admin'
      [user_hash] => '-----------------------'
      [sa …))
#11 /data/SugarBean.php(5017):  SugarBean->load_relationship(     rel_name: 'reports_to_link')
#12 /data/SugarBean.php(4966):  SugarBean->fill_in_link_field(
     linkFieldName: 'reports_to_link', 
     def: Array (
      [name] => 'reports_to_name'
      [rname] => 'last_name'
      [id_name] => 'reports_to_id'
      [vname] => 'LBL_REPORTS_TO_NAME'
      [type] => 'relate'
      [isnull] => 'true'
   …))
#13 /include/SugarObjects/templates/person/Person.php(126):  SugarBean->fill_in_relationship_fields()
#14 /data/SugarBean.php(4563):  Person->fill_in_relationship_fields()
#15 /include/SugarObjects/templates/person/Person.php(113):  SugarBean->retrieve(
     id: '1', 
     encode: 1, 
     deleted: 1)
#16 /modules/Users/User.php(1068):  Person->retrieve(
     id: '1', 
     encode: 1, 
     deleted: 1)
#17 /modules/Users/authentication/SugarAuthenticate/SugarAuthenticateUser.php(138):  User->retrieve(     id: '1')
#18 /modules/Users/authentication/SugarAuthenticate/SugarAuthenticate.php(254):  SugarAuthenticateUser->loadUserOnSession(     user_id: '1')
#19 /modules/Users/authentication/SugarAuthenticate/SugarAuthenticate.php(208):  SugarAuthenticate->postSessionAuthenticate()
#20 /modules/Users/authentication/AuthenticationController.php(208):  SugarAuthenticate->sessionAuthenticate()
#21 /include/MVC/SugarApplication.php(164):  AuthenticationController->sessionAuthenticate()
#22 /include/MVC/SugarApplication.php(101):  SugarApplication->loadUser()
#23 /index.php(52):  SugarApplication->execute()

Request Overview:Array (
      [$_REQUEST] => Array (
        [module] => 'Emails'
        [action] => 'ComposeView'
        [return_module] => 'Emails'
        [return_action] => 'index'
        [XDEBUG_SESSION_START] => 'phpstorm'
      [Selected $GLOBALS] => Array (
        [SuiteCRM Version] => '7.10.27'
        [db] => 'suitecrm'
        [BASE_DIR] => '/mnt/c/Users/Pgr/PhpstormProjects/SuiteCRM'
      [SugarController] => Array (
        [entryPointFile] => ''
        [processTasksHistory] => ''
        [handleActionTasksHistory] => ''
        [redirect_url] => ''
      )

Expected Behavior

I am convinced these are false positives, they should just be given a lower ranking, not FATAL (they don't block execution).

Possible Fix

This was introduced here: #7795

I agree that not having a module name there is a serious error - but historically these functions have always behaved differently and most of the code calling these will handle the false returned from the GetBean just fine.

Either

1. Leave the current code with all these calls with blank field_defs, and give the message a really low level like NOTICE

or, preferably

1. Fix all these messages from getting generated, by improving the functions further up in the call stack, and give this message a higher level like ERROR to be a more significant warning for the future.

Steps to Reproduce

Just load a few views until you see the error. It shouldn't take long to find one. A session start should produce several of these.

Context

"False-positive" FATALs cause chaos in Forums troubleshooting.

Your Environment

• SuiteCRM Version used: 7.10.27

[holdusback]

Can confirme thoses error message in my error log. since update 7.11.15

[ebogaard]

About the unneccessary fatal-log levels used: SuiteCRM uses these for about everything, which is very annoying as they often give false indications and/or make people try to find a cause for those while they mean little to nothing in "real life".

Example: when the phpmailer finds an incorrectly formatted e-mail address: FATAL in the log.
Maybe for that sub-sub-process, but not for SuiteCRM as a whole.

This makes monitoring the logfile very time consuming and leads to lots of false positives. Should we make a separate issue for this? Or do you want to use this issue as the main issue for this problem? Then you should probably change the subject to something like: "Unneccessary FATALs: reassess log levels used throughout SuiteCRM"

[Mac-Rae]

Hi @pgorod,

This issue has been confirmed to exist and is replicable in the latest 7.10.x version.

Thanks :+1: