Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
2 tasks
diderich opened this issue May 12, 2024 · 4 comments
Open
2 tasks

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

diderich opened this issue May 12, 2024 · 4 comments
Assignees
Labels
bug Something isn't working
Milestone

Comments

@diderich
Copy link

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

📷 Screenshot of configuration

ConfReport

📝 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
Copy link

krawalli commented Jun 3, 2024

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
Copy link

This worked, thank you

@deepti4666
Copy link

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

@deepti4666
Copy link

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

@rskrzypczak rskrzypczak added the bug Something isn't working label Jun 11, 2024
@rskrzypczak rskrzypczak transferred this issue from YetiForceCompany/YetiForceCRM Sep 12, 2024
@rskrzypczak rskrzypczak reopened this Sep 12, 2024
@rskrzypczak rskrzypczak added this to the 7.0.3 milestone Sep 13, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

4 participants