TYPO3 Core

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

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

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.

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?

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:{}}}')

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

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

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

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

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

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?

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

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

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

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

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

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