Project

General

Profile

Actions

Bug #86941

closed

Logger instances in scheduler tasks are deserialized with outdated paths

Added by Helmut Hummel over 5 years ago. Updated about 4 years ago.

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

100%

Estimated time:
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 4 (0 open4 closed)

Related to TYPO3 Core - Bug #87094: A Symfony Console based scheduler task can't be executed and breaks the scheduler moduleClosed2018-12-07

Actions
Related to TYPO3 Core - Bug #87261: Upgrade wizard for scheduler tasks with invalid Logger instance pathsClosedJoerg Boesche2018-12-21

Actions
Related to TYPO3 Core - Bug #87780: Extbase Task should call parents __sleep and __wakeup MethodsClosed2019-02-25

Actions
Related to TYPO3 Core - Bug #86785: Calling scheduler command on CLI throws error if not in /var/www/htmlClosed2018-12-21

Actions
Actions #1

Updated by Josef Glatz about 5 years ago

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

Updated by Josef Glatz about 5 years ago

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

Updated by Achim Fritz about 5 years ago

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

Updated by Benni Mack about 5 years ago

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

Updated by Benni Mack about 5 years ago

  • Status changed from New to Needs Feedback

Hey Helmut,

thanks for your report.

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

Actions #6

Updated by Helmut Hummel about 5 years ago

@Benni Mack: 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.

Actions #7

Updated by Ralf Merz about 5 years 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.

Actions #8

Updated by Helmut Hummel about 5 years 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?

Actions #9

Updated by Ralf Merz about 5 years 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:{}}}')
Actions #10

Updated by Gerrit Code Review about 5 years 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

Actions #11

Updated by Helmut Hummel about 5 years 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?

Actions #12

Updated by Helmut Hummel about 5 years 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?

Actions #13

Updated by Ralf Merz about 5 years ago

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

Actions #14

Updated by Gerrit Code Review about 5 years 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

Actions #15

Updated by Gerrit Code Review about 5 years 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

Actions #16

Updated by Ralf Merz about 5 years 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.

Actions #17

Updated by Gerrit Code Review about 5 years 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

Actions #18

Updated by Helmut Hummel about 5 years 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?

Actions #19

Updated by Ralf Merz about 5 years 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

Actions #20

Updated by Gerrit Code Review about 5 years 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

Actions #21

Updated by Gerrit Code Review about 5 years 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

Actions #22

Updated by Gerrit Code Review almost 5 years 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

Actions #23

Updated by Helmut Hummel almost 5 years ago

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

Updated by Benni Mack almost 5 years ago

  • Status changed from Resolved to Closed
Actions #25

Updated by Gerrit Code Review over 4 years ago

  • Status changed from Closed to Under Review

Patch set 6 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

Actions #26

Updated by Gerrit Code Review over 4 years ago

Patch set 7 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

Actions #27

Updated by Gerrit Code Review about 4 years 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/+/62801

Actions #28

Updated by Helmut Hummel about 4 years ago

  • Status changed from Under Review to Resolved
Actions #29

Updated by Gerrit Code Review about 4 years ago

  • Status changed from Resolved to Under Review

Patch set 2 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/+/62801

Actions #30

Updated by Helmut Hummel about 4 years ago

  • Status changed from Under Review to Resolved
Actions #31

Updated by Benni Mack about 4 years ago

  • Status changed from Resolved to Closed
Actions

Also available in: Atom PDF