Bug #86941

Logger instances in scheduler tasks are deserialized with outdated paths

Added by Helmut Hummel 6 months ago. Updated 18 days ago.

Status:
Closed
Priority:
Should have
Assignee:
-
Category:
-
Target version:
-
Start date:
2018-11-16
Due date:
% Done:

100%

TYPO3 Version:
9
PHP Version:
Tags:
Complexity:
Is Regression:
Sprint Focus:

Description

Scheduler serializes tasks and stores them in the database.
If these tasks store a logger instance (e.g. by using the LoggerAwareTrait), this instance will be serialized as well and will point to the wrong path, e.g. when TYPO3 is moved to a different folder
or path changes due to deployments.

This issue became much more prevalent with the addition of LoggerAwareTrait to \TYPO3\CMS\Scheduler\Task\AbstractTask
Now every single task will store outdated logger instances pointing to very likely broken directories


Related issues

Related to TYPO3 Core - Bug #87094: A Symfony Console based scheduler task can't be executed and breaks the scheduler module Closed 2018-12-07
Related to TYPO3 Core - Bug #87261: Upgrade wizard for scheduler tasks with invalid Logger instance paths Closed 2018-12-21
Related to TYPO3 Core - Bug #87780: Extbase Task should call parents __sleep and __wakeup Methods Under Review 2019-02-25
Related to TYPO3 Core - Bug #86785: Calling scheduler command on CLI throws error if not in /var/www/html Closed 2018-12-21

Associated revisions

Revision 682c732a (diff)
Added by Helmut Hummel about 1 month ago

[BUGFIX] Fix serialization of loggers

Only dealing with PHP file resource in writers is not
enough to properly initialize a logger on wakeup.

A logger has to log with a new request IDs and possibly completely new writers
and processors due to configuration changes in the meantime.

Therefore the __sleep and __wakeup methods are removed in the FileWriter
and new methods are added to the logger instance to make sure a
wakeup will have a correctly configured logger instance.

Resolves: #86941
Resolves: #87261
Releases: master, 9.5
Change-Id: Ia36e251404eae2bdf0dfdf52ace7dcf1815ec456
Reviewed-on: https://review.typo3.org/c/Packages/TYPO3.CMS/+/60325
Tested-by: Ralf Merz <>
Tested-by: TYPO3com <>
Tested-by: Susanne Moog <>
Reviewed-by: Ralf Merz <>
Reviewed-by: Susanne Moog <>

Revision 7b6f6b87 (diff)
Added by Helmut Hummel about 1 month ago

[BUGFIX] Fix serialization of loggers

Only dealing with PHP file resource in writers is not
enough to properly initialize a logger on wakeup.

A logger has to log with a new request IDs and possibly completely new writers
and processors due to configuration changes in the meantime.

Therefore the __sleep and __wakeup methods are removed in the FileWriter
and new methods are added to the logger instance to make sure a
wakeup will have a correctly configured logger instance.

Resolves: #86941
Resolves: #87261
Releases: master, 9.5
Change-Id: Ia36e251404eae2bdf0dfdf52ace7dcf1815ec456
Reviewed-on: https://review.typo3.org/c/Packages/TYPO3.CMS/+/60472
Tested-by: TYPO3com <>
Tested-by: Susanne Moog <>
Reviewed-by: Susanne Moog <>

History

#1 Updated by Josef Glatz 4 months ago

  • Related to Bug #87094: A Symfony Console based scheduler task can't be executed and breaks the scheduler module added

#2 Updated by Josef Glatz 4 months ago

  • Related to Bug #87261: Upgrade wizard for scheduler tasks with invalid Logger instance paths added

#3 Updated by Achim Fritz 3 months ago

  • Related to Bug #87780: Extbase Task should call parents __sleep and __wakeup Methods added

#4 Updated by Benni Mack 3 months ago

  • Related to Bug #86785: Calling scheduler command on CLI throws error if not in /var/www/html added

#5 Updated by Benni Mack 3 months ago

  • Status changed from New to Needs Feedback

Hey Helmut,

thanks for your report.

Is this fixed with #86785 - https://review.typo3.org/59237 ?

#6 Updated by Helmut Hummel 3 months ago

@Benni: Depends how you look at it. https://review.typo3.org/#/c/Packages/TYPO3.CMS/+/59800/ shows, that the implemented solution needs adaption in all scheduler tasks that implement __sleep and/or __wakeup. e.g. AbstractSolrTask implements __sleep which does not reset the logger, which leads to the logger to be serialized again and not properly set in __wakeup because the logger is only restored when property is null.

Thus https://review.typo3.org/#/c/Packages/TYPO3.CMS/+/59259/ appeared, which introduces an upgrade wizard to remove the logger from serialized tasks, which basically needs to be run all the time, not only once so that solr tasks have a proper instance.

This is why I proposed several times to remove the logger in \TYPO3\CMS\Scheduler\Task\AbstractTask::unsetScheduler and restore it in \TYPO3\CMS\Scheduler\Task\AbstractTask::setScheduler, which solves all issues (makes 59259 obsolete) and also is a more stable solution as it is much more unlikely that custom task implementations override unsetScheduler and setScheduler methods.

So yes, it is partly solved, but the solution is not as robust as it could be. I would do a change request, but since my comments were ignored as of now, I didn't feel like fighting for this one.

#7 Updated by Ralf Merz 2 months ago

Hi,

for me this is not solved yet.
The FileWriter tries to open a path that probably does not exist anymore. E.g. if you work with releases and hav something like

home/web10/htdocs/R20181212161053/var/log/typo3_77ab733d5a.log

where the "R********" thing is the release folder. This may change locally and on remote server.

I don't know if it was a good thing to just check if logFile is writable in FileWriters __wakeup() ?

/**
     * Allow serialization of logger - reinitialize log file on unserializing
     */
    public function __wakeup()
    {
        self::$logFileHandlesCount[$this->logFile]++;
        $this->setLogFile($this->logFile && is_writeable($this->logFile) ?: $this->getDefaultLogFileName());
    }

With that I am able to open the Scheduler module without exception and can open the tasks and save them.

#8 Updated by Helmut Hummel 2 months ago

Ralf Merz wrote:

for me this is not solved yet.

Which task causes issues for you? Is it the solr indexer task by any chance?

#9 Updated by Ralf Merz 2 months ago

Hi Helmut,

no, in this case it is the Scheduler task for my google sitemap
https://extensions.typo3.org/extension/inm_googlesitemap/
And there are project specific product import tasks.

There is a logger defined (not by us, by core) like example from such a task (this is the serialized field from scheduler task):

unserialize('O:48:"TYPO3\\CMS\\Scheduler\\Task\\FileStorageIndexingTask":9:{s:10:"storageUid";i:1;s:10:"' . "\0" . '*' . "\0" . 'taskUid";i:31;s:11:"' . "\0" . '*' . "\0" . 'disabled";b:1;s:19:"' . "\0" . '*' . "\0" . 'runOnNextCronJob";b:0;s:12:"' . "\0" . '*' . "\0" . 'execution";O:29:"TYPO3\\CMS\\Scheduler\\Execution":6:{s:8:"' . "\0" . '*' . "\0" . 'start";i:1544690094;s:6:"' . "\0" . '*' . "\0" . 'end";i:1544690094;s:11:"' . "\0" . '*' . "\0" . 'interval";i:0;s:11:"' . "\0" . '*' . "\0" . 'multiple";i:0;s:10:"' . "\0" . '*' . "\0" . 'cronCmd";s:0:"";s:23:"' . "\0" . '*' . "\0" . 'isNewSingleExecution";b:0;}s:16:"' . "\0" . '*' . "\0" . 'executionTime";i:1544690094;s:14:"' . "\0" . '*' . "\0" . 'description";s:0:"";s:12:"' . "\0" . '*' . "\0" . 'taskGroup";i:0;s:9:"' . "\0" . '*' . "\0" . 'logger";O:25:"TYPO3\\CMS\\Core\\Log\\Logger":5:{s:7:"' . "\0" . '*' . "\0" . 'name";s:48:"TYPO3.CMS.Scheduler.Task.FileStorageIndexingTask";s:12:"' . "\0" . '*' . "\0" . 'requestId";s:13:"24f12eeaf6d2b";s:18:"' . "\0" . '*' . "\0" . 'minimumLogLevel";i:7;s:10:"' . "\0" . '*' . "\0" . 'writers";a:8:{i:0;a:2:{i:0;O:36:"TYPO3\\CMS\\Core\\Log\\Writer\\FileWriter":1:{s:10:"' . "\0" . '*' . "\0" . 'logFile";s:63:"/home/web10/htdocs/R20181212161053/var/log/typo3_77ab733d5a.log";}i:1;O:42:"TYPO3\\CMS\\Adminpanel\\Log\\InMemoryLogWriter":0:{}}i:1;a:2:{i:0;r:22;i:1;r:24;}i:2;a:2:{i:0;r:22;i:1;r:24;}i:3;a:2:{i:0;r:22;i:1;r:24;}i:4;a:2:{i:0;r:22;i:1;r:24;}i:5;a:1:{i:0;r:24;}i:6;a:1:{i:0;r:24;}i:7;a:1:{i:0;r:24;}}s:13:"' . "\0" . '*' . "\0" . 'processors";a:0:{}}}')

#10 Updated by Gerrit Code Review 2 months ago

  • Status changed from Needs Feedback to Under Review

Patch set 1 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/60306

#11 Updated by Helmut Hummel 2 months ago

  • Status changed from Under Review to Needs Feedback

Ralf Merz wrote:

for me this is not solved yet.

Which task causes issues for you? Is it the solr indexer task by any chance?

#12 Updated by Helmut Hummel 2 months ago

  • Status changed from Needs Feedback to Under Review

Helmut Hummel wrote:

Ralf Merz wrote:

for me this is not solved yet.

Which task causes issues for you? Is it the solr indexer task by any chance?

@Ralf: can you check whether https://review.typo3.org/c/Packages/TYPO3.CMS/+/60306 helps?

#13 Updated by Ralf Merz 2 months ago

@Helmut: I'll check that. Hopefully tonight, but have to leave for now until about 8.30pm
I'll let you know :)

#14 Updated by Gerrit Code Review 2 months ago

Patch set 2 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/60306

#15 Updated by Gerrit Code Review 2 months ago

Patch set 3 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/60306

#16 Updated by Ralf Merz 2 months ago

@Helmut: Sorry, the 60306 patch does not help.
I still get the exception:

(1/1) #1170251401 RuntimeException
Could not create directory "/home/web10/htdocs/R20181212161053/var/log/"!
in /home/web20/htdocs/R20190213100002/htdocs/typo3/sysext/core/Classes/Utility/GeneralUtility.php line 2172
            } while (!is_dir($currentPath) && $separatorPosition !== false);
            $result = @mkdir($fullDirectoryPath, $permissionMask, true);
            // Check existence of directory again to avoid race condition. Directory could have get created by another process between previous is_dir() and mkdir()
            if (!$result && !@is_dir($fullDirectoryPath)) {
                throw new \RuntimeException('Could not create directory "' . $fullDirectoryPath . '"!', 1170251401);
            }
        }
        return $firstCreatedPath;
    }
at TYPO3\CMS\Core\Utility\GeneralUtility::createDirectoryPath('/home/web10/htdocs/R20181212161053/var/log/')
in /home/web20/htdocs/R20190213100002/htdocs/typo3/sysext/core/Classes/Utility/GeneralUtility.php line 2140
            trigger_error('Second argument $deepDirectory of GeneralUtility::mkdir_deep() will be removed in TYPO3 v10.0, use a combined string as first argument instead.', E_USER_DEPRECATED);
            $fullPath .= ltrim($deepDirectory, '/');
        }
        if ($fullPath !== '/' && !is_dir($fullPath)) {
            $firstCreatedPath = static::createDirectoryPath($fullPath);
            if ($firstCreatedPath !== '') {
                static::fixPermissions($firstCreatedPath, true);
            }
        }
at TYPO3\CMS\Core\Utility\GeneralUtility::mkdir_deep('/home/web10/htdocs/R20181212161053/var/log')
in /home/web20/htdocs/R20190213100002/htdocs/typo3/sysext/core/Classes/Log/Writer/FileWriter.php line 222
            return;
        }
        $logFileDirectory = PathUtility::dirname($this->logFile);
        if (!@is_dir($logFileDirectory)) {
            GeneralUtility::mkdir_deep($logFileDirectory);
            // create .htaccess file if log file is within the site path
            if (PathUtility::getCommonPrefix([Environment::getPublicPath() . '/', $logFileDirectory]) === (Environment::getPublicPath() . '/')) {
                // only create .htaccess, if we created the directory on our own
                $this->createHtaccessFile($logFileDirectory . '/.htaccess');
at TYPO3\CMS\Core\Log\Writer\FileWriter->createLogFile()
in /home/web20/htdocs/R20190213100002/htdocs/typo3/sysext/core/Classes/Log/Writer/FileWriter.php line 193
        if (isset(self::$logFileHandles[$this->logFile]) && is_resource(self::$logFileHandles[$this->logFile] ?? false)) {
            return;
        }

        $this->createLogFile();
        self::$logFileHandles[$this->logFile] = fopen($this->logFile, 'a');
        if (!is_resource(self::$logFileHandles[$this->logFile])) {
            throw new \RuntimeException('Could not open log file "' . $this->logFile . '"', 1321804422);
        }
at TYPO3\CMS\Core\Log\Writer\FileWriter->openLogFile()
in /home/web20/htdocs/R20190213100002/htdocs/typo3/sysext/core/Classes/Log/Writer/FileWriter.php line 123
                );
            }
        }
        $this->logFile = $logFile;
        $this->openLogFile();

        return $this;
    }

at TYPO3\CMS\Core\Log\Writer\FileWriter->setLogFile('/home/web10/htdocs/R20181212161053/var/log/typo3_77ab733d5a.log')
in /home/web20/htdocs/R20190213100002/htdocs/typo3/sysext/core/Classes/Log/Writer/FileWriter.php line 281
     */
    public function __wakeup()
    {
        self::$logFileHandlesCount[$this->logFile]++;
        $this->setLogFile($this->logFile ?: $this->getDefaultLogFileName());
    }

    /**
     * Property 'logFile' should be kept
at TYPO3\CMS\Core\Log\Writer\FileWriter->__wakeup()
at unserialize('O:48:"TYPO3\\CMS\\Scheduler\\Task\\FileStorageIndexingTask":9:{s:10:"storageUid";i:1;s:10:"' . "\0" . '*' . "\0" . 'taskUid";i:31;s:11:"' . "\0" . '*' . "\0" . 'disabled";b:1;s:19:"' . "\0" . '*' . "\0" . 'runOnNextCronJob";b:0;s:12:"' . "\0" . '*' . "\0" . 'execution";O:29:"TYPO3\\CMS\\Scheduler\\Execution":6:{s:8:"' . "\0" . '*' . "\0" . 'start";i:1544690094;s:6:"' . "\0" . '*' . "\0" . 'end";i:1544690094;s:11:"' . "\0" . '*' . "\0" . 'interval";i:0;s:11:"' . "\0" . '*' . "\0" . 'multiple";i:0;s:10:"' . "\0" . '*' . "\0" . 'cronCmd";s:0:"";s:23:"' . "\0" . '*' . "\0" . 'isNewSingleExecution";b:0;}s:16:"' . "\0" . '*' . "\0" . 'executionTime";i:1544690094;s:14:"' . "\0" . '*' . "\0" . 'description";s:0:"";s:12:"' . "\0" . '*' . "\0" . 'taskGroup";i:0;s:9:"' . "\0" . '*' . "\0" . 'logger";O:25:"TYPO3\\CMS\\Core\\Log\\Logger":5:{s:7:"' . "\0" . '*' . "\0" . 'name";s:48:"TYPO3.CMS.Scheduler.Task.FileStorageIndexingTask";s:12:"' . "\0" . '*' . "\0" . 'requestId";s:13:"24f12eeaf6d2b";s:18:"' . "\0" . '*' . "\0" . 'minimumLogLevel";i:7;s:10:"' . "\0" . '*' . "\0" . 'writers";a:8:{i:0;a:2:{i:0;O:36:"TYPO3\\CMS\\Core\\Log\\Writer\\FileWriter":1:{s:10:"' . "\0" . '*' . "\0" . 'logFile";s:63:"/home/web10/htdocs/R20181212161053/var/log/typo3_77ab733d5a.log";}i:1;O:42:"TYPO3\\CMS\\Adminpanel\\Log\\InMemoryLogWriter":0:{}}i:1;a:2:{i:0;r:22;i:1;r:24;}i:2;a:2:{i:0;r:22;i:1;r:24;}i:3;a:2:{i:0;r:22;i:1;r:24;}i:4;a:2:{i:0;r:22;i:1;r:24;}i:5;a:1:{i:0;r:24;}i:6;a:1:{i:0;r:24;}i:7;a:1:{i:0;r:24;}}s:13:"' . "\0" . '*' . "\0" . 'processors";a:0:{}}}')
in /home/web20/htdocs/R20190213100002/htdocs/typo3/sysext/scheduler/Classes/Controller/SchedulerModuleController.php line 906
                $isRunning = false;
                $showAsDisabled = false;
                // Restore the serialized task and pass it a reference to the scheduler object
                /** @var \TYPO3\CMS\Scheduler\Task\AbstractTask|ProgressProviderInterface $task */
                $task = unserialize($schedulerRecord['serialized_task_object']);
                $class = get_class($task);
                if ($class === '__PHP_Incomplete_Class' && preg_match('/^O:[0-9]+:"(?P<classname>.+?)"/', $schedulerRecord['serialized_task_object'], $matches) === 1) {
                    $class = $matches['classname'];
                }

As you can see, the difference here is a project with "web10" which has been copied to "web20". The paths in the serialized thing in scheduler do now mismatch.

Thx.

#17 Updated by Gerrit Code Review 2 months ago

Patch set 4 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/60306

#18 Updated by Helmut Hummel 2 months ago

Ralf Merz wrote:

@Helmut: Sorry, the 60306 patch does not help.
I still get the exception:

Can you give me more context? Like which scheduler task is affected and how exactly you are executing the task (command line, web).

Also can you post the full trace somewhere, so that I can see how the code ends up in the logging?

#19 Updated by Ralf Merz 2 months ago

Hi @Helmut,

the exception is thrown when I open the Scheduler module.
If I look into the DB, where we have about 20 Scheduler Tasks, all of them having such a "logger" entry pointing to a file form the "other" instance where the dump came from.
This is stored in the "serialized_task_object" field. I don't know when the Scheduler module adds this logger information to the "serialized_task_object".

I will send you the whole trace in a snippet in slack.

Thx
Ralf

#20 Updated by Gerrit Code Review 2 months ago

Patch set 5 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/60306

#21 Updated by Gerrit Code Review 2 months ago

Patch set 1 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/60325

#22 Updated by Gerrit Code Review about 1 month ago

Patch set 1 for branch 9.5 of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/60472

#23 Updated by Helmut Hummel about 1 month ago

  • Status changed from Under Review to Resolved
  • % Done changed from 0 to 100

#24 Updated by Benni Mack 18 days ago

  • Status changed from Resolved to Closed

Also available in: Atom PDF