SuiteCRM 8.3.0 Login only works after several attempts ('Error occurred while retrieving records")

📦 Install & Upgrade Help
,
1

Hi,

  • After upgrading from SuiteCRM 7.x to 8.3.0, I now have the following problem.
    Login requires several attempts to work. It is arbitrary how many attempts are required, in some cases the 1st login works, in others 10 attempts are required.
    The login always fails with the error message ‘Error occurred while retrieving records’.
    A 404 error occurs in the browser error console (Firefox and Chrome), which corresponds to the apache2 protocol (see below).
    Once logged in, everything works without problems except logging out.
    The logout itself hangs with the animated SuiteCRM logo and after reload (F5) is still logged in.

  • I have also tried this one, and at first I had the impression that it helped, but now I don’t think so anymore.: Invalid CSRF token - #3 by kingfisher77

I am open to any idea.
Best regards,
Peter

  • Environment:
    ** The SuiteCRM runs on a VM in a Proxmox
    ** Host
   Static hostname: suitecrm
         Icon name: computer-vm
           Chassis: vm
        Machine ID: bc..............
           Boot ID: c6..............
    Virtualization: kvm
  Operating System: Debian GNU/Linux 11 (bullseye)
            Kernel: Linux 5.10.0-23-amd64
      Architecture: x86-64

** PHP

PHP 7.4.33 (cli) (built: Feb 22 2023 20:07:47) ( NTS )
Copyright (c) The PHP Group
Zend Engine v3.4.0, Copyright (c) Zend Technologies
    with Zend OPcache v7.4.33, Copyright (c), by Zend Technologies
  • Log
    ** apache2 log “/var/log/apache2/other_vhosts_access.log”
suitecrm.mydomain.local:80 192.168.1.2 - - [05/Jul/2023:09:43:48 +0200] "POST /login HTTP/1.1" 200 860 "http://192.168.2.66/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36"
suitecrm.mydomain.local:80 192.168.1.2 - - [05/Jul/2023:09:43:48 +0200] "POST /api/graphql HTTP/1.1" 301 463 "http://192.168.2.66/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36"
suitecrm.mydomain.local:80 192.168.1.2 - - [05/Jul/2023:09:43:48 +0200] "POST /api/graphql HTTP/1.1" 200 1466 "http://192.168.2.66/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36"
suitecrm.mydomain.local:80 192.168.1.2 - - [05/Jul/2023:09:43:48 +0200] "GET /session-status HTTP/1.1" 200 851 "http://192.168.2.66/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36"
suitecrm.mydomain.local:80 192.168.1.2 - - [05/Jul/2023:09:43:48 +0200] "GET /api/index.php?action=Login&module=Users HTTP/1.1" 404 896 "http://192.168.2.66/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36"
suitecrm.mydomain.local:80 192.168.1.2 - - [05/Jul/2023:09:43:48 +0200] "GET /session-status HTTP/1.1" 200 851 "http://192.168.2.66/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36"
suitecrm.mydomain.local:80 192.168.1.2 - - [05/Jul/2023:09:43:48 +0200] "POST /api/graphql HTTP/1.1" 200 153000 "http://192.168.2.66/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36"
suitecrm.mydomain.local:80 192.168.1.2 - - [05/Jul/2023:09:43:48 +0200] "POST /api/graphql HTTP/1.1" 200 152827 "http://192.168.2.66/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36"
1 Like
2

Try to clear cookies in your browser for suitecrm site.
If it doesn’t help, set log level to debug in system settings and check public/legacy/suitecrm.log for lines after “We have an authenticated user id”.

3

Check your PHP version from Admin / Diagnostics / phpinfo, not from the CLI. It might be different.

4

Hi,

From Diagnostic: Is also “PHP Version 7.4.33”

I will enable and check the debug log when the Service is not in use today or tomorrow.

5

Hello, it took longer thank expected.

In de debug log I found some lines with "We have an authenticated user id”

Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] current_language is: en_us
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Found cache backend SugarCacheFile
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Found cache backend SugarCachesMash
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Found cache backend SugarCacheWincache
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Found cache backend SugarCacheAPC
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Found cache backend SugarCacheRedis
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Found cache backend SugarCacheMemcached
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Found cache backend SugarCacheMemcache
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Found cache backend SugarCacheZend
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Found cache backend SugarCacheMemory
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Mon Jul 10 08:44:52 2023 [616][-none-][INFO] Found language file: en_us.lang.php
Mon Jul 10 08:44:52 2023 [616][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Mon Jul 10 08:44:52 2023 [616][-none-][INFO] Query Execution Time:0.0002739429473877
Mon Jul 10 08:44:52 2023 [616][-none-][INFO] Query:SELECT category, name, value FROM config
Mon Jul 10 08:44:52 2023 [616][-none-][INFO] Query Execution Time:0.00018811225891113
Mon Jul 10 08:44:52 2023 [616][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system' AND deleted = 0
Mon Jul 10 08:44:52 2023 [616][-none-][INFO] Query Execution Time:0.00019192695617676
Mon Jul 10 08:44:52 2023 [616][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '1a8896bf-c8d1-a629-579c-60ed7ebc10ca'
Mon Jul 10 08:44:52 2023 [616][-none-][INFO] Query Execution Time:0.00022196769714355
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Hook called: ::after_entry_point
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Including module specific hook file for custom/modules
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Including Ext hook file for custom/application
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Hook called: ::after_session_start
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Unable to find SugarController:: index
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] We have an authenticated user id: 57e2a7f3-5f46-a6e7-7b14-60ed81e14677
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Hook called: Users::before_retrieve
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Retrieve User : SELECT users.* FROM users  WHERE users.id = '57e2a7f3-5f46-a6e7-7b14-60ed81e14677' AND users.deleted=0
Mon Jul 10 08:44:52 2023 [616][-none-][DEBUG] Limit Query:SELECT users.* FROM users  WHERE users.id = '57e2a7f3-5f46-a6e7-7b14-60ed81e14677' AND users.deleted=0 Start: 0 count: 1
Mon Jul 10 08:44:52 2023 [616][-none-][INFO] Query:SELECT users.* FROM users  WHERE users.id = '57e2a7f3-5f46-a6e7-7b14-60ed81e14677' AND users.deleted=0 LIMIT 0,1
Mon Jul 10 08:44:52 2023 [616][-none-][INFO] Query Execution Time:0.00031781196594238
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][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
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query Execution Time:0.00033092498779297
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query:SELECT u1.first_name, u1.last_name from users  u1, users  u2 where u1.id = u2.reports_to_id AND u2.id = '57e2a7f3-5f46-a6e7-7b14-60ed81e14677' and u1.deleted=0
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query Execution Time:0.00033402442932129
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][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 = '57e2a7f3-5f46-a6e7-7b14-60ed81e14677'
                    AND ear.deleted = 0
                ORDER BY ear.reply_to_address, ear.primary_address DESC
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query Execution Time:0.0003969669342041
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Hook called: Users::after_retrieve
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] FACTOR AUTH: User does`nt need factor auth
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Current user is: MYUSERNAME
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Current user is: MYUSERNAME
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] setting cookie ck_login_id_20 to 57e2a7f3-5f46-a6e7-7b14-60ed81e14677
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] setting cookie ck_login_language_20 to en_us
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] current_language is: en_us
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Found language file: en_us.lang.php
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Module:Administration using file: index
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEPRECATED] Array
(
)

Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][WARN] CSS File Dawn/yui.css not found
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Hook called: Administration::after_ui_frame
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Creating new instance of hook class hooks without parameters
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Creating new instance of hook class AssignGroups without parameters
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] SecuritySuite: Get SecuritySuite Enabled Modules: SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = 'SecurityGroups' OR rhs_module='SecurityGroups')
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = 'SecurityGroups' OR rhs_module='SecurityGroups')
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query Execution Time:0.00057792663574219
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Hook called: ::after_ui_footer
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Creating new instance of hook class AssignGroups without parameters
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Hook called: ::server_round_trip
Mon Jul 10 08:44:52 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Calling MySQLi::disconnect()
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] current_language is: en_us
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Found cache backend SugarCacheFile
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Found cache backend SugarCachesMash
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Found cache backend SugarCacheWincache
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Found cache backend SugarCacheAPC
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Found cache backend SugarCacheRedis
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Found cache backend SugarCacheMemcached
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Found cache backend SugarCacheMemcache
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Found cache backend SugarCacheZend
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Found cache backend SugarCacheMemory
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Mon Jul 10 08:44:53 2023 [616][-none-][INFO] Found language file: en_us.lang.php
Mon Jul 10 08:44:53 2023 [616][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Mon Jul 10 08:44:53 2023 [616][-none-][INFO] Query Execution Time:0.0015871524810791
Mon Jul 10 08:44:53 2023 [616][-none-][INFO] Query:SELECT category, name, value FROM config
Mon Jul 10 08:44:53 2023 [616][-none-][INFO] Query Execution Time:0.00020408630371094
Mon Jul 10 08:44:53 2023 [616][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system' AND deleted = 0
Mon Jul 10 08:44:53 2023 [616][-none-][INFO] Query Execution Time:0.00018787384033203
Mon Jul 10 08:44:53 2023 [616][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '1a8896bf-c8d1-a629-579c-60ed7ebc10ca'
Mon Jul 10 08:44:53 2023 [616][-none-][INFO] Query Execution Time:0.0001680850982666
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Hook called: ::after_entry_point
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Including module specific hook file for custom/modules
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Including Ext hook file for custom/application
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Hook called: ::after_session_start
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Unable to find SugarController:: index
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] We have an authenticated user id: 57e2a7f3-5f46-a6e7-7b14-60ed81e14677
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Hook called: Users::before_retrieve
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Including module specific hook file for custom/modules/Users
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Retrieve User : SELECT users.* FROM users  WHERE users.id = '57e2a7f3-5f46-a6e7-7b14-60ed81e14677' AND users.deleted=0
Mon Jul 10 08:44:53 2023 [616][-none-][DEBUG] Limit Query:SELECT users.* FROM users  WHERE users.id = '57e2a7f3-5f46-a6e7-7b14-60ed81e14677' AND users.deleted=0 Start: 0 count: 1
Mon Jul 10 08:44:53 2023 [616][-none-][INFO] Query:SELECT users.* FROM users  WHERE users.id = '57e2a7f3-5f46-a6e7-7b14-60ed81e14677' AND users.deleted=0 LIMIT 0,1
Mon Jul 10 08:44:53 2023 [616][-none-][INFO] Query Execution Time:0.00034713745117188
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][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
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query Execution Time:0.00029397010803223
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query:SELECT u1.first_name, u1.last_name from users  u1, users  u2 where u1.id = u2.reports_to_id AND u2.id = '57e2a7f3-5f46-a6e7-7b14-60ed81e14677' and u1.deleted=0
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query Execution Time:0.010076999664307
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] SugarBean[User].load_relationships, Loading relationship (reports_to_link).
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][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 = '57e2a7f3-5f46-a6e7-7b14-60ed81e14677'
                    AND ear.deleted = 0
                ORDER BY ear.reply_to_address, ear.primary_address DESC
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Query Execution Time:0.00055885314941406
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Hook called: Users::after_retrieve
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] FACTOR AUTH: --------------------- CHECK FACTOR AUtH ---------------------
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] FACTOR AUTH: -------------------------------------------------------------
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] FACTOR AUTH: User needs factor auth, request is not Logout
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] FACTOR AUTH: User does`nt need factor auth
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Current user is: MYUSERNAME
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Current user is: MYUSERNAME
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] setting cookie ck_login_id_20 to 57e2a7f3-5f46-a6e7-7b14-60ed81e14677
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] setting cookie ck_login_language_20 to en_us
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] current_language is: en_us
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][INFO] Found language file: en_us.lang.php
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Hook called: ::server_round_trip
Mon Jul 10 08:44:53 2023 [616][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][DEBUG] Calling MySQLi::disconnect()
Mon Jul 10 08:44:53 2023 [610][-none-][DEBUG] current_language is: en_us
Mon Jul 10 08:44:53 2023 [610][-none-][DEBUG] Found cache backend SugarCacheFile
Mon Jul 10 08:44:53 2023 [610][-none-][DEBUG] Found cache backend SugarCachesMash
Mon Jul 10 08:44:53 2023 [610][-none-][DEBUG] Found cache backend SugarCacheWincache
Mon Jul 10 08:44:53 2023 [610][-none-][DEBUG] Found cache backend SugarCacheAPC
Mon Jul 10 08:44:53 2023 [610][-none-][DEBUG] Found cache backend SugarCacheRedis

and there also this kind of errors:

Mon Jul 10 08:44:53 2023 [610][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][ERROR] Unable to find relationship emails_email_templates
Mon Jul 10 08:44:53 2023 [610][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][WARN] emails_email_templates for emails_email_templates failed to load
--
Mon Jul 10 08:44:53 2023 [610][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][ERROR] Unable to find relationship emails_email_templates
Mon Jul 10 08:44:53 2023 [610][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][WARN] emails_email_templates_idb for emails_email_templates failed to load
--
Mon Jul 10 08:44:53 2023 [610][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][ERROR] Unable to find relationship emails_email_templates
Mon Jul 10 08:44:53 2023 [610][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][WARN] emails_email_templates for emails_email_templates failed to load
--
Mon Jul 10 08:44:53 2023 [610][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][ERROR] Unable to find relationship emails_email_templates
Mon Jul 10 08:44:53 2023 [610][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][WARN] emails_email_templates_idb for emails_email_templates failed to load
--
Mon Jul 10 08:44:53 2023 [512][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][ERROR] Unable to find relationship emails_email_templates
Mon Jul 10 08:44:53 2023 [512][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][WARN] emails_email_templates for emails_email_templates failed to load
--
Mon Jul 10 08:44:53 2023 [512][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][ERROR] Unable to find relationship emails_email_templates
Mon Jul 10 08:44:53 2023 [512][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][WARN] emails_email_templates_idb for emails_email_templates failed to load
--
Mon Jul 10 08:44:53 2023 [512][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][ERROR] Unable to find relationship projects_contacts_resources
Mon Jul 10 08:44:53 2023 [512][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][WARN] project_resource for projects_contacts_resources failed to load
--
Mon Jul 10 08:44:53 2023 [512][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][ERROR] Unable to find relationship am_projecttemplates_contacts_resources
Mon Jul 10 08:44:53 2023 [512][57e2a7f3-5f46-a6e7-7b14-60ed81e14677][WARN] am_projecttemplates_resources for am_projecttemplates_contacts_resources failed to load

Up to now I try also php8.0 and 8.2, clearing cache using ./bin/console cache:clear and clean browser.

Any Idea?

6

Does this log contain failed login attempt ? I was expected to see some lines about session destroying, but there aren’t any in provided logs.

Judging from the apache log, request to /api/graphql resulted in 301 redirect to index.php?action=Login&module=Users, which used /api as a base url.

[05/Jul/2023:09:43:48 +0200] "POST /api/graphql HTTP/1.1" 301
[05/Jul/2023:09:43:48 +0200] "GET /api/index.php?action=Login&module=Users HTTP/1.1" 404

There is one place without logs where it could happen:

In any case it means SuiteCRM is unable to find user session.
Do you use simple apache2 with libapache2-mod-php or some sort of php-fpm or maybe different php session store backend ?

7

Hi,

  • I check the log again, and can not find any “login failed” events and no messages about destroying sessions.
  • I use the straight forward linux installation of apache2 and php, no special stuff.
ii  apache2                       2.4.56-1~deb11u2               amd64        Apache HTTP Server
ii  apache2-bin                   2.4.56-1~deb11u2               amd64        Apache HTTP Server (modules and other binary files)
ii  apache2-data                  2.4.56-1~deb11u2               all          Apache HTTP Server (common files)
ii  apache2-utils                 2.4.56-1~deb11u2               amd64        Apache HTTP Server (utility programs for web servers)
ii  libapache2-mod-php7.4         7.4.33-1+deb11u3               amd64        server-side, HTML-embedded scripting language (Apache 2 module)
  • I will try to check the stuff you linked me from Git.

Thanks so far.

8

I have v8.3.1 and this error persists and I have some snapshots of the error that might be able to help? I was logged in and went away for an hour approximately. This screen appeared when I returned to the laptop. I captured pictures of the “inspect” on browser and I copied the content of the tabs like Payload etc. Maybe this can assist because it looks like something is expiring or not being renewed.

2023-07-18 09_53_28-SuiteCRM and 98 more pages - Personal - Microsoft​ Edge
2023-07-18 09_53_28-SuiteCRM and 98 more pages - Personal - Microsoft​ Edge1102×697 38.2 KB

Then I inspected the browser network settings where graphql showed 408 error:
2023-07-18 10_00_16-SuiteCRM and 98 more pages - Personal - Microsoft​ Edge
2023-07-18 10_00_16-SuiteCRM and 98 more pages - Personal - Microsoft​ Edge1581×1251 132 KB

Here are the content of the Payload:

{operationName: "getRecordList", variables: {module: "alerts", limit: 5, offset: 0,…},…}
operationName
: 
"getRecordList"
query
: 
"query getRecordList($module: String!, $limit: Int, $offset: Int, $criteria: Iterable, $sort: Iterable) {\n  getRecordList(module: $module, limit: $limit, offset: $offset, criteria: $criteria, sort: $sort) {\n    id\n    _id\n    meta\n    records\n    __typename\n  }\n}\n"
variables
: 
{module: "alerts", limit: 5, offset: 0,…}
criteria
: 
{name: "default", filters: {}, orderBy: "snooze", sortOrder: "desc", preset: {type: "alerts"}}
filters
: 
{}
name
: 
"default"
orderBy
: 
"snooze"
preset
: 
{type: "alerts"}
type
: 
"alerts"
sortOrder
: 
"desc"
limit
: 
5
module
: 
"alerts"
offset
: 
0
sort
: 
{sortOrder: "DESC", orderBy: "snooze"}

Here is the PREVIEW tab with invalid CSRF token error:

{@context: "/api/contexts/Error", @type: "hydra:Error", hydra:title: "An error occurred",…}
@context
: 
"/api/contexts/Error"
@type
: 
"hydra:Error"
hydra:description
: 
"Invalid CSRF token"
hydra:title
: 
"An error occurred"

Here is the content of the RESPONSE tab

{"@context":"\/api\/contexts\/Error","@type":"hydra:Error","hydra:title":"An error occurred","hydra:description":"Invalid CSRF token"}

Here is the cookie tab:

2023-07-18 10_17_19-SuiteCRM and 98 more pages - Personal - Microsoft​ Edge
2023-07-18 10_17_19-SuiteCRM and 98 more pages - Personal - Microsoft​ Edge1552×458 53.7 KB

Perhaps this will assist in narrowing the search?

9

What I noticed during the test is the following.
The first message in the Bwroser console (F12) says that the login is successful.
After that, data is retrieved and then there are problems with the CSRF token and I end up back at the login with the familiar message “Error occurred while retrieving records”.
When I look at the generated cookie, it contains a different CSRF token than the one requested.
If, on the other hand, the login is successful and I can retrieve the content, the requested and stored CSRF token are identical.

  • Is this normal?
  • How is the CSRF token actually generated?
10

Hi,

my biggest question is, why does this happen, see (1)?
It make no sense to run an API-Call with index.php… as parameter.

why_does_this_happen
why_does_this_happen1960×1192 263 KB

Regards,
Peter

11

I would suspect that your mod_rewrites are not configured properly yet, and you’re triggering this part of the public/.htaccess

<IfModule !mod_rewrite.c>
    <IfModule mod_alias.c>
        # When mod_rewrite is not available, we instruct a temporary redirect of
        # the start page to the front controller explicitly so that the website
        # and the generated links can still be used.
        RedirectMatch 307 ^/$ /index.php/
        # RedirectTemp cannot be used instead
    </IfModule>
</IfModule>

… although I would expect to see a 307 getting returned there :thinking:

12

Today I had a big WTF moment.

Hi,

first of all, the problem is (maybe) solved.

What was the problem, better the root of the problems.
It was a combination of my v7 > v8 migration problem ([Solved] Migration 7.x to 8.x allways fails with "Unauthorized access to administration")

SuiteCRM Finalize Upgrade
============

Running: legacy-post-upgrade
step: legacy-post-upgrade | status: failed
Unexpected error running Legacy Post Upgrade
Unauthorized access to administration

and the “blank page” Problem.

When I set up a v8 environment to migrate from v7, no NEW DB was generated because the migration rebuilds the v7 DB.
So in the process the

SuiteCRM Finalize Upgrade
============

Running: legacy-post-upgrade
step: legacy-post-upgrade | status: failed
Unexpected error running Legacy Post Upgrade
Unauthorized access to administration

Problem.
I had solved this by disabling the if (!is_admin($current_user)) check in the source code, as suggested.

The migration then went through but after that I had the blank page problem (api/graphql not found) problem.

I had solved this by creating a backup of the migrated instance and restoring it to a freshly installed SuiteCRM instance of the same version.

After that SuiteCRM worked again, but I got the login problems that required many attempts.

Today I set up a new server with a blank SuiteCRM v8.3.0 (same version as our running SuiteCRM) and started a file by file and table by table comparison.
To narrow it down I imported the database table by table to the new server and check the login after each import is causing problems.

Fortunately I started with “accounts” followed by “users” tables. All “account” tables work fine, but after importing “users” the login stopped working.

When I check the “suitecrm.users” table and see that the first generated user id=1, I have some gut feeling. So I updated the id of the imported user id=1 to id=2 and restored the original id=1 user from the new server from a snapshot.
And, lo and behold, everything worked fine.

All in all, when you set up a new instance of SuiteCRM, never overwrite the id=1 user.
When restoring a SuiteCRM instance,

  • perform a full installation of a new SuiteCRM version,
  • save the id=1 user from the DB,
  • restore the old DB from your backup.
  • change the ID of the restored user id=1 to 2
  • insert the saved id=1 user.

I really wonder what exactly is attached to this 1st user that causes massive problems when it comes from another SuiteCRM installation.

So far so good, thanks to all have tried to help,
Best regards,
Peter

2 Likes
13

I did not read everything, but a quick feed from us (we had the same problem): it was a matter of cache, since if we replace in file .env

APP_ENV=prod

with

APP_ENV=qa

we could login right away: so then we just cleaned all caches

14

I have a similar issue with 8.4.0, and I’ve seen it in 8.3.x as well. I have a complete working environment on my local machine, with an identical database, identical Apache configuration, identical PHP configuration. The only thing that differs, is that the one that isn’t working is a “live site”, hosted on a remote machine, using SSL.

I see a “Login success” in the console, and then it fails on a subsequent call to this url:

https://crm.hostname.com/api/index.php?action=Login&module=Users

I have cleared caches, via bin/console, and by using rm, I have copied all files from the working environment. Still it won’t work.

22:23:33.624
XHRPOST
https://crm.hostname.com/login
[HTTP/1.1 200 OK 803ms]

22:23:34.431 Login success dist_core___ivy_ngcc___fesm2015_core_js-_0b011-es2015.ca6d992010619201adb7.js:17:3124
22:23:34.441
XHRPOST
https://crm.hostname.com/api/graphql
[HTTP/1.1 200 OK 1232ms]

22:23:34.443
XHRPOST
https://crm.hostname.com/api/graphql
[HTTP/1.1 301 Moved Permanently 815ms]

22:23:35.262
XHRGET
https://crm.hostname.com/api/index.php?action=Login&module=Users
[HTTP/1.1 404 Not Found 700ms]

22:23:35.693
XHRGET
https://crm.hostname.com/session-status
[HTTP/1.1 200 OK 662ms]

22:23:36.366
GET
https://crm.hostname.com/legacy/themes/default/images/company_logo.png
[HTTP/1.1 200 OK 0ms]

22:23:36.380
XHRGET
https://crm.hostname.com/session-status
[HTTP/1.1 200 OK 659ms]

22:23:37.051
XHRPOST
https://crm.hostname.com/api/graphql
[HTTP/1.1 200 OK 847ms]

22:23:37.925
XHRPOST
https://crm.hostname.com/api/graphql
[HTTP/1.1 200 OK 816ms]
15

Where are these settings “on disk”? (Since we can’t access “System settings” inside SuiteCRM) :thinking:

16

Searching through the code for this rather weird call, I get this:

legacy/include/MVC/SugarApplication.php:                SugarApplication::redirect('index.php?action=Login&module=Users');
legacy/include/MVC/SugarApplication.php:            SugarApplication::redirect('index.php?action=Login&module=Users');
legacy/modules/Users/Changenewpassword.php:    header('location:index.php?action=Login&module=Users');
legacy/modules/Users/LoggedOut.php:    'LOGIN_URL'  => 'index.php?action=Login&module=Users',
legacy/modules/Users/authentication/SAML2Authenticate/lib/onelogin/settings.php:$spBase = $GLOBALS['sugar_config']['site_url'].'/index.php?action=Login&module=Users';
legacy/modules/Users/authentication/SugarAuthenticate/SugarAuthenticate.php:            header("Location: index.php?action=Login&module=Users" . $GLOBALS['app']->getLoginRedirect());
legacy/modules/Users/authentication/SugarAuthenticate/SugarAuthenticate.php:            header("Location: index.php?action=Login&module=Users&loginErrorMessage=LBL_SESSION_EXPIRED");
legacy/modules/Users/authentication/SugarAuthenticate/SugarAuthenticate.php:        SugarApplication::redirect('index.php?action=Login&module=Users' . $loginVars);
17

Thank you so much for the hint to the users-table and the id=1! I had a really hard time with this login problem.

I was not able to fix it the mentioned way because I was in a different situation, but it helped me anyways. If anyone searches for this, I want to share my solution too:

In our setup we use LDAP authentication and SuiteCRM 8.5.1 with a reverse-proxy. We never migrated from 7.x, but I always have the same problem as you mentioned with the Unauthorized access to administration-error.

  • First, there were some duplicated users on suitecrm.users (I guess from LDAP-setup?), all deactivated but with the same username. I deleted all those.
  • Afterwards, I enabled the administrator-user with id=1 again (was disabled). The fields with values “Terminated” and “Inactive” must be “Active”.
  • Special in our case: I changed external_auth_only=1 on all accounts, including the administrator.

This seems to do the trick, now the login works first try.