YetiForceCompany / YetiForce

One of the most innovative CRM systems that supports mainly business processes and allows for customization according to your needs. Be ahead of your competition and implement YetiForce!
https://yetiforce.com
4 stars 3 forks source link

[bug] E_WARNING unserialize() when running cron job #7

Open diderich opened 6 months ago

diderich commented 6 months ago

🐞 bug report

⁉️ Describe the bug

When running the cron job, I get the following warning messages:

2024-05-12 09:29:55 [info] - Task start: LBL_SESSION_CLEANER
2024-05-12 09:29:55 [error] -    The task returned a message: 
E_WARNING: unserialize(): Extra data starting at offset 72 of 607 bytes in /opt/crm7/app/Session/File.php, line 114
E_WARNING: unserialize(): Extra data starting at offset 20 of 521 bytes in /opt/crm7/app/Session/File.php, line 114
E_WARNING: unserialize(): Extra data starting at offset 44 of 489 bytes in /opt/crm7/app/Session/File.php, line 114
E_WARNING: unserialize(): Extra data starting at offset 88 of 434 bytes in /opt/crm7/app/Session/File.php, line 114
E_WARNING: unserialize(): Extra data starting at offset 15 of 331 bytes in /opt/crm7/app/Session/File.php, line 114
E_WARNING: unserialize(): Extra data starting at offset 48 of 301 bytes in /opt/crm7/app/Session/File.php, line 114
E_WARNING: unserialize(): Extra data starting at offset 13 of 243 bytes in /opt/crm7/app/Session/File.php, line 114
E_WARNING: unserialize(): Extra data starting at offset 23 of 215 bytes in /opt/crm7/app/Session/File.php, line 114
E_WARNING: unserialize(): Extra data starting at offset 4 of 170 bytes in /opt/crm7/app/Session/File.php, line 114
E_WARNING: unserialize(): Extra data starting at offset 50 of 156 bytes in /opt/crm7/app/Session/File.php, line 114
E_WARNING: unserialize(): Extra data starting at offset 6 of 102 bytes in /opt/crm7/app/Session/File.php, line 114
E_WARNING: unserialize(): Extra data starting at offset 7 of 85 bytes in /opt/crm7/app/Session/File.php, line 114
2024-05-12 09:29:55 [info] -    End task, time: 0.02

The error log file contains a lot of the following type of errors (only a subset is reproduced here):

E_WARNING: unserialize(): Extra data starting at offset 72 of 607 bytes in /opt/crm7/app/Session/File.php, line 114
#0 app/Session/File.php:114  >>  unserialize('s:64:"095c71f4156d4168fe567b28b2f33796b5d282b8fa97ce3ec5761d4431b5873c";last_activity|d:1715498979.054015;fingerprint|s:36:"d520c7a8-421b-4563-b955-f5abc56b97ec";user_agent|s:80:"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:125.0) Gecko/20100101 Firefox/125.0";UserAuthMethod|s:8:"PASSWORD";app_unique_key|s:40:"554cb1fc342aa04c32160ed2ac19d18ae0d9eb72";user_name|s:6:"claude";full_user_name|s:15:"Diderich Claude";authenticated_user_id|i:5;DashBoard|a:1:{s:4:"Home";a:1:{s:15:"LastDashBoardId";i:1;}}lvs|a:0:{}baseUserId|s:0:"";relatedView|a:1:{s:12:"OSSEmployees";a:1:{s:15:"SSalesProcesses";s:4:"List";}}',[])
#1 app/Session/File.php:83  >>  App\Session\File->unserializePhp('CSP_TOKEN|s:64:"095c71f4156d4168fe567b28b2f33796b5d282b8fa97ce3ec5761d4431b5873c";last_activity|d:1715498979.054015;fingerprint|s:36:"d520c7a8-421b-4563-b955-f5abc56b97ec";user_agent|s:80:"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:125.0) Gecko/20100101 Firefox/125.0";UserAuthMethod|s:8:"PASSWORD";app_unique_key|s:40:"554cb1fc342aa04c32160ed2ac19d18ae0d9eb72";user_name|s:6:"claude";full_user_name|s:15:"Diderich Claude";authenticated_user_id|i:5;DashBoard|a:1:{s:4:"Home";a:1:{s:15:"LastDashBoardId";i:1;}}lvs|a:0:{}baseUserId|s:0:"";relatedView|a:1:{s:12:"OSSEmployees";a:1:{s:15:"SSalesProcesses";s:4:"List";}}')
#2 app/Session/File.php:25  >>  App\Session\File->unserialize('CSP_TOKEN|s:64:"095c71f4156d4168fe567b28b2f33796b5d282b8fa97ce3ec5761d4431b5873c";last_activity|d:1715498979.054015;fingerprint|s:36:"d520c7a8-421b-4563-b955-f5abc56b97ec";user_agent|s:80:"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:125.0) Gecko/20100101 Firefox/125.0";UserAuthMethod|s:8:"PASSWORD";app_unique_key|s:40:"554cb1fc342aa04c32160ed2ac19d18ae0d9eb72";user_name|s:6:"claude";full_user_name|s:15:"Diderich Claude";authenticated_user_id|i:5;DashBoard|a:1:{s:4:"Home";a:1:{s:15:"LastDashBoardId";i:1;}}lvs|a:0:{}baseUserId|s:0:"";relatedView|a:1:{s:12:"OSSEmployees";a:1:{s:15:"SSalesProcesses";s:4:"List";}}')
#3 modules/Vtiger/crons/SessionCleaner.php:32  >>  App\Session\File->clean()
#4 cron.php:100  >>  Vtiger_SessionCleaner_Cron->process()
E_WARNING: unserialize(): Extra data starting at offset 20 of 521 bytes in /opt/crm7/app/Session/File.php, line 114
#0 app/Session/File.php:114  >>  unserialize('d:1715498979.054015;fingerprint|s:36:"d520c7a8-421b-4563-b955-f5abc56b97ec";user_agent|s:80:"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:125.0) Gecko/20100101 Firefox/125.0";UserAuthMethod|s:8:"PASSWORD";app_unique_key|s:40:"554cb1fc342aa04c32160ed2ac19d18ae0d9eb72";user_name|s:6:"claude";full_user_name|s:15:"Diderich Claude";authenticated_user_id|i:5;DashBoard|a:1:{s:4:"Home";a:1:{s:15:"LastDashBoardId";i:1;}}lvs|a:0:{}baseUserId|s:0:"";relatedView|a:1:{s:12:"OSSEmployees";a:1:{s:15:"SSalesProcesses";s:4:"List";}}',[])
#1 app/Session/File.php:83  >>  App\Session\File->unserializePhp('CSP_TOKEN|s:64:"095c71f4156d4168fe567b28b2f33796b5d282b8fa97ce3ec5761d4431b5873c";last_activity|d:1715498979.054015;fingerprint|s:36:"d520c7a8-421b-4563-b955-f5abc56b97ec";user_agent|s:80:"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:125.0) Gecko/20100101 Firefox/125.0";UserAuthMethod|s:8:"PASSWORD";app_unique_key|s:40:"554cb1fc342aa04c32160ed2ac19d18ae0d9eb72";user_name|s:6:"claude";full_user_name|s:15:"Diderich Claude";authenticated_user_id|i:5;DashBoard|a:1:{s:4:"Home";a:1:{s:15:"LastDashBoardId";i:1;}}lvs|a:0:{}baseUserId|s:0:"";relatedView|a:1:{s:12:"OSSEmployees";a:1:{s:15:"SSalesProcesses";s:4:"List";}}')
#2 app/Session/File.php:25  >>  App\Session\File->unserialize('CSP_TOKEN|s:64:"095c71f4156d4168fe567b28b2f33796b5d282b8fa97ce3ec5761d4431b5873c";last_activity|d:1715498979.054015;fingerprint|s:36:"d520c7a8-421b-4563-b955-f5abc56b97ec";user_agent|s:80:"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:125.0) Gecko/20100101 Firefox/125.0";UserAuthMethod|s:8:"PASSWORD";app_unique_key|s:40:"554cb1fc342aa04c32160ed2ac19d18ae0d9eb72";user_name|s:6:"claude";full_user_name|s:15:"Diderich Claude";authenticated_user_id|i:5;DashBoard|a:1:{s:4:"Home";a:1:{s:15:"LastDashBoardId";i:1;}}lvs|a:0:{}baseUserId|s:0:"";relatedView|a:1:{s:12:"OSSEmployees";a:1:{s:15:"SSalesProcesses";s:4:"List";}}')
#3 modules/Vtiger/crons/SessionCleaner.php:32  >>  App\Session\File->clean()
#4 cron.php:100  >>  Vtiger_SessionCleaner_Cron->process()
E_WARNING: unserialize(): Extra data starting at offset 44 of 489 bytes in /opt/crm7/app/Session/File.php, line 114
#0 app/Session/File.php:114  >>  unserialize('s:36:"d520c7a8-421b-4563-b955-f5abc56b97ec";user_agent|s:80:"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:125.0) Gecko/20100101 Firefox/125.0";UserAuthMethod|s:8:"PASSWORD";app_unique_key|s:40:"554cb1fc342aa04c32160ed2ac19d18ae0d9eb72";user_name|s:6:"claude";full_user_name|s:15:"Diderich Claude";authenticated_user_id|i:5;DashBoard|a:1:{s:4:"Home";a:1:{s:15:"LastDashBoardId";i:1;}}lvs|a:0:{}baseUserId|s:0:"";relatedView|a:1:{s:12:"OSSEmployees";a:1:{s:15:"SSalesProcesses";s:4:"List";}}',[])
#1 app/Session/File.php:83  >>  App\Session\File->unserializePhp('CSP_TOKEN|s:64:"095c71f4156d4168fe567b28b2f33796b5d282b8fa97ce3ec5761d4431b5873c";last_activity|d:1715498979.054015;fingerprint|s:36:"d520c7a8-421b-4563-b955-f5abc56b97ec";user_agent|s:80:"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:125.0) Gecko/20100101 Firefox/125.0";UserAuthMethod|s:8:"PASSWORD";app_unique_key|s:40:"554cb1fc342aa04c32160ed2ac19d18ae0d9eb72";user_name|s:6:"claude";full_user_name|s:15:"Diderich Claude";authenticated_user_id|i:5;DashBoard|a:1:{s:4:"Home";a:1:{s:15:"LastDashBoardId";i:1;}}lvs|a:0:{}baseUserId|s:0:"";relatedView|a:1:{s:12:"OSSEmployees";a:1:{s:15:"SSalesProcesses";s:4:"List";}}')
#2 app/Session/File.php:25  >>  App\Session\File->unserialize('CSP_TOKEN|s:64:"095c71f4156d4168fe567b28b2f33796b5d282b8fa97ce3ec5761d4431b5873c";last_activity|d:1715498979.054015;fingerprint|s:36:"d520c7a8-421b-4563-b955-f5abc56b97ec";user_agent|s:80:"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:125.0) Gecko/20100101 Firefox/125.0";UserAuthMethod|s:8:"PASSWORD";app_unique_key|s:40:"554cb1fc342aa04c32160ed2ac19d18ae0d9eb72";user_name|s:6:"claude";full_user_name|s:15:"Diderich Claude";authenticated_user_id|i:5;DashBoard|a:1:{s:4:"Home";a:1:{s:15:"LastDashBoardId";i:1;}}lvs|a:0:{}baseUserId|s:0:"";relatedView|a:1:{s:12:"OSSEmployees";a:1:{s:15:"SSalesProcesses";s:4:"List";}}')
#3 modules/Vtiger/crons/SessionCleaner.php:32  >>  App\Session\File->clean()
#4 cron.php:100  >>  Vtiger_SessionCleaner_Cron->process()
....

πŸ”₯ How to trigger the error

Steps to reproduce the behavior:

  1. Run cron job php cron.php
  2. See error

πŸ‘Ž Actual Behavior

πŸ‘ Expected Behavior

Error messages are saved in errors.log and cron/xxxx.log

πŸ‘· Testing

No errors occur.

πŸ“ PHP/Apache/Nginx/Browser/CRM Logs

🌍 Your Environment

Environment Version / Name
YetiForce 7.0.1
PHP 8.3.7

❓ Additional context

Add any other context about the problem here.

❗️ Inform the community if you solve the problem

krawalli commented 5 months ago

can confirm those log entries.

Its caused here: (/app/Session/File.php) around line 106

        while ($offset < \strlen($session)) {
            if (!strstr(substr($session, $offset), '|')) {
                throw new \App\Exceptions\IllegalValue('invalid data, remaining: ' . substr($session, $offset));
            }
            $pos = strpos($session, '|', $offset);
            $num = $pos - $offset;
            $varName = substr($session, $offset, $num);
            $offset += $num + 1;
            $data = unserialize(substr($session, $offset), ['allowed_classes' => false]);
            $return[$varName] = $data;
            $offset += \strlen(serialize($data));
        }

It uses the complete string from $offset position to be de-serialzed. Since only the very next item could be de-serialized it causes that warnings.

Replace those "while" block with (it also does some serialize fixing if parts where missing):

$matches = [];
if(preg_match_all('/(\w+)\|(.*?)(?=(\w+)\||$)/', $session, $matches)) {
        foreach($matches[1] as $i=>$k) {
            $v = $matches[2][$i];
            if(preg_match_all('/s:(\d+):"([^"]*?)"/', $v, $matches2)) {
                foreach($matches2[1] as $i=>$len) {
                    if(($newlen=strlen($matches2[2][$i]))!=$len) {
                        $v=str_replace("s:{$len}:\"{$matches2[2][$i]}\"","s:{$newlen}:\"{$matches2[2][$i]}\"",$v);
                    }
                }
            }
            if(substr_count($v, "{")>substr_count($v, "}")) {
                $v .= str_repeat("}", substr_count($v, "{")-substr_count($v, "}"));
            }
            if(!in_array(substr($v,-1), [";","}"])){
                $v .= ";";
            }
            $return[$k] = unserialize($v);
        }
    }
deepti4666 commented 5 months ago

This worked, thank you

deepti4666 commented 5 months ago

this doesn't allow the user to stay in the portal

deepti4666 commented 5 months ago

I put this in the "while" blocks

Replace those "while" block with (it also does some serialize fixing if parts where missing):

$matches = [];
if(preg_match_all('/(\w+)\|(.*?)(?=(\w+)\||$)/', $session, $matches)) {
        foreach($matches[1] as $i=>$k) {
            $v = $matches[2][$i];
            if(preg_match_all('/s:(\d+):"([^"]*?)"/', $v, $matches2)) {
                foreach($matches2[1] as $i=>$len) {
                    if(($newlen=strlen($matches2[2][$i]))!=$len) {
                        $v=str_replace("s:{$len}:\"{$matches2[2][$i]}\"","s:{$newlen}:\"{$matches2[2][$i]}\"",$v);
                    }
                }
            }
            if(substr_count($v, "{")>substr_count($v, "}")) {
                $v .= str_repeat("}", substr_count($v, "{")-substr_count($v, "}"));
            }
            if(!in_array(substr($v,-1), [";","}"])){
                $v .= ";";
            }
            $return[$k] = unserialize($v);
        }
    }

& it allows the user to stay logged in