[bug] E_WARNING unserialize() when running cron job

Question

[bug] E_WARNING unserialize() when running cron job

Opened this issue 2 months ago · 4 comments

🐞 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:

Run cron job php cron.php
See error

👎 Actual Behavior

👍 Expected Behavior

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

👷 Testing

No errors occur.

I confirm that I tested it at https://gitstable.yetiforce.com
I confirm that I tested it at https://gitdeveloper.yetiforce.com
Cannot be tested

📷 Screenshot of configuration

📝 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

Answer 1 · 2024-06-03T14:44:37.000Z

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);
        }
    }

Answer 2 · 2024-06-10T16:34:57.000Z

This worked, thank you

Answer 3 · 2024-06-11T13:36:48.000Z

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

Answer 4 · 2024-06-11T13:43:39.000Z

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