BUGFIX: rendering often fails while content publishes are happening

Classes/NodeRendering/Infrastructure/RedisRenderingQueue.php

@@ -123,6 +123,37 @@ public function registerRenderingAttempt(
         );
     }
 
+    /**
+     * Tells the orchestrator that the given node has been rendered, so that it can add the document to the content
+     * release right away - before an editor's publish gets the chance to flush it from the content cache again.
+     *
+     * Call this before {@see removeRenderingJobFromReservedList()}: the orchestrator stops waiting as soon as no
+     * rendering is in progress anymore, and then drains this list a last time.
+     *
+     * @throws \JsonException
+     */
+    public function reportRenderedJob(
+        ContentReleaseIdentifier $contentReleaseIdentifier,
+        EnumeratedNode $enumeratedNode,
+    ): void {
+        $this->redisClientManager->getPrimaryRedis()->rPush(
+            $this->redisKeyService->getRedisKeyForPostfix($contentReleaseIdentifier, 'renderedJobs'),
+            json_encode($enumeratedNode, JSON_THROW_ON_ERROR),
+        );
+    }
+
+    public function fetchNextRenderedJob(ContentReleaseIdentifier $contentReleaseIdentifier): ?EnumeratedNode
+    {
+        $nextEntry = $this->redisClientManager
+            ->getPrimaryRedis()
+            ->lPop($this->redisKeyService->getRedisKeyForPostfix($contentReleaseIdentifier, 'renderedJobs'));
+        if (!is_string($nextEntry)) {
+            return null;
+        }
+
+        return EnumeratedNode::fromJsonString($nextEntry);
+    }
+
     /**
      * @param ContentReleaseIdentifier $contentReleaseIdentifier
      * @param EnumeratedNode $enumeratedNode
@@ -171,6 +202,7 @@ public function flush(ContentReleaseIdentifier $contentReleaseIdentifier)
             $this->redisKeyService->getRedisKeyForPostfix($contentReleaseIdentifier, 'renderingJobQueue'),
             $this->redisKeyService->getRedisKeyForPostfix($contentReleaseIdentifier, 'inProgressRenderings'),
             $this->redisKeyService->getRedisKeyForPostfix($contentReleaseIdentifier, 'renderAttempts'),
+            $this->redisKeyService->getRedisKeyForPostfix($contentReleaseIdentifier, 'renderedJobs'),
         );
     }
 }

Classes/NodeRendering/NodeRenderOrchestrator.php

@@ -20,8 +20,11 @@
 use Flowpack\DecoupledContentStore\NodeRendering\ProcessEvents\ExitEvent;
 use Flowpack\DecoupledContentStore\NodeRendering\ProcessEvents\RenderingIterationCompletedEvent;
 use Flowpack\DecoupledContentStore\NodeRendering\ProcessEvents\RenderingQueueFilledEvent;
+use Flowpack\DecoupledContentStore\PrepareContentRelease\Dto\ContentReleaseMetadata;
 use Flowpack\DecoupledContentStore\PrepareContentRelease\Infrastructure\RedisContentReleaseService;
 use Neos\Flow\Annotations as Flow;
+use Neos\Fusion\Core\Cache\ContentCache;
+use Neos\Neos\Fusion\Helper\CachingHelper;
 
 /**
  * TODO: explain concept of Working Set
@@ -98,15 +101,24 @@ class NodeRenderOrchestrator
      */
     protected $redisContentReleaseSizeService;
 
+    #[Flow\Inject]
+    protected ContentCache $contentCache;
+
+    #[Flow\Inject]
+    protected CachingHelper $cachingHelper;
+
+    #[Flow\InjectConfiguration('nodeRendering.flushDocumentCacheOnRetry')]
+    protected bool $flushDocumentCacheOnRetry;
+
     private const EXIT_ERRORSTATUSCODE_RELEASE_ALREADY_COMPLETED = 1;
     private const EXIT_ERRORSTATUSCODE_EMPTY_ENUMERATION = 2;
     private const EXIT_ERRORSTATUSCODE_RETRY_LIMIT_REACHED = 3;
     private const EXIT_ERRORSTATUSCODE_RENDERING_ERRORS = 4;
 
     /**
      * How often the very same set of nodes may be scheduled in a row before we give up on them. The rendering gets
-     * one real retry (which flushes the content cache for these nodes, {@see NodeRenderer::flushContentCacheForNode()})
-     * before this kicks in.
+     * one real retry (which flushes the content cache for these nodes, {@see flushContentCacheForRetry()}) before
+     * this kicks in.
      */
     private const MAX_ITERATIONS_WITHOUT_PROGRESS = 3;
 
@@ -121,6 +133,12 @@ public function renderContentRelease(
         ContentReleaseLogger $contentReleaseLogger,
     ): \Generator {
         $releaseMetadata = $this->redisContentReleaseService->fetchMetadataForContentRelease($contentReleaseIdentifier);
+        if ($releaseMetadata === null) {
+            throw new \RuntimeException(sprintf(
+                'No metadata found for content release %s.',
+                $contentReleaseIdentifier->getIdentifier(),
+            ));
+        }
         $renderStatus = $releaseMetadata->getStatus();
 
         if ($renderStatus->hasCompleted()) {
@@ -185,6 +203,9 @@ public function renderContentRelease(
 
             // goTroughEnumeratedNodesFillContentReleaseAndCheckWhatStillNeedsToBeDone
             $nodesScheduledForRendering = [];
+            // Retries are queued only after their cache entries are flushed, see flushContentCacheForRetry(); the first
+            // iteration flushes nothing, so its jobs are queued right away to keep the render workers busy.
+            $queueWhileChecking = $i === 1 || !$this->flushDocumentCacheOnRetry;
             foreach ($currentEnumeration as $enumeratedNode) {
                 assert($enumeratedNode instanceof EnumeratedNode);
 
@@ -213,36 +234,20 @@ public function renderContentRelease(
                     ]);
                     // the rendered document was not found, or has holes. so we need to re-render.
                     $nodesScheduledForRendering[] = $enumeratedNode;
-                    $this->redisRenderingQueue->appendRenderingJob($contentReleaseIdentifier, $enumeratedNode);
+                    if ($queueWhileChecking) {
+                        $this->redisRenderingQueue->appendRenderingJob($contentReleaseIdentifier, $enumeratedNode);
+                    }
                 }
             }
 
             if (empty($nodesScheduledForRendering)) {
                 // we have NO nodes scheduled for rendering anymore, so that means we FINISHED successfully.
-                $contentReleaseLogger->info(sprintf(
-                    'Everything rendered completely in %d seconds. Finishing RenderOrchestrator',
-                    time() - $startTime,
-                ));
-
-                // The release is complete now, so this is the point where we can determine its size once. Calculating
-                // it is expensive, which is why the Backend UI relies on this stored value instead of re-calculating it.
-                $contentReleaseSize = $this->redisContentReleaseSizeService->calculateReleaseSize(
-                    RedisInstanceIdentifier::primary(),
+                yield from $this->completeContentRelease(
                     $contentReleaseIdentifier,
+                    $contentReleaseLogger,
+                    $releaseMetadata,
+                    $startTime,
                 );
-                $contentReleaseLogger->info(sprintf('Content release size: %.2f MB', $contentReleaseSize));
-
-                // info to all renderers that we finished, and they should terminate themselves gracefully.
-                $this->redisContentReleaseService->setContentReleaseMetadata(
-                    $contentReleaseIdentifier,
-                    $releaseMetadata->withStatus(NodeRenderingCompletionStatus::success())
-                        ->withEndTime(new \DateTimeImmutable())
-                        ->withContentReleaseSize($contentReleaseSize),
-                    RedisInstanceIdentifier::primary(),
-                );
-
-                // Exit successfully.
-                yield ExitEvent::createWithStatusCode(0);
                 return;
             }
 
@@ -282,6 +287,13 @@ public function renderContentRelease(
                 return;
             }
 
+            if (!$queueWhileChecking) {
+                $this->flushContentCacheForRetry($nodesScheduledForRendering, $i, $contentReleaseLogger);
+                foreach ($nodesScheduledForRendering as $enumeratedNode) {
+                    $this->redisRenderingQueue->appendRenderingJob($contentReleaseIdentifier, $enumeratedNode);
+                }
+            }
+
             // we remember the $totalJobsCount for displaying the rendering progress
             $totalJobsCount = count($nodesScheduledForRendering);
             // $remainingJobsCount is needed to figure out
@@ -295,25 +307,40 @@ public function renderContentRelease(
             // Now, we need to wait for the rendering to complete.
             yield RenderingQueueFilledEvent::create();
             $contentReleaseLogger->info('Waiting for renderings to complete...');
-            $waitTimer = 0;
+            $lastDataPointTime = microtime(true);
+            $nodesAddedToContentRelease = [];
 
             while (
                 $this->redisRenderingQueue->numberOfQueuedJobs($contentReleaseIdentifier) > 0
                 || $this->redisRenderingQueue->numberOfRenderingsInProgress($contentReleaseIdentifier) > 0
             ) {
+                $passDeadline = microtime(true) + 1;
+                $nodesAddedToContentRelease += $this->addReportedRenderingsToContentRelease(
+                    $contentReleaseIdentifier,
+                    $contentReleaseLogger,
+                    $passDeadline,
+                );
                 $this->redisRenderingStatisticsStore->replaceLastStatisticsIteration($contentReleaseIdentifier, RenderingStatistics::create(
                     $remainingJobsCount,
                     $totalJobsCount,
                     $renderingsPerSecondDataPoints,
                 ));
 
-                sleep(1);
-                $waitTimer++;
-                if (($waitTimer % 10) === 0) {
+                // A backlog of reported renderings uses up the whole pass and is worked off without pausing.
+                $secondsLeftInPass = $passDeadline - microtime(true);
+                if ($secondsLeftInPass > 0) {
+                    usleep((int) ($secondsLeftInPass * 1_000_000));
+                }
+                // Measured in wall-clock time: the deadline is only checked between two renderings, so a pass can take
+                // longer than a second.
+                $secondsSinceLastDataPoint = microtime(true) - $lastDataPointTime;
+                if ($secondsSinceLastDataPoint >= 10) {
+                    $lastDataPointTime = microtime(true);
                     $previousRemainingJobs = $remainingJobsCount;
                     $remainingJobsCount = $this->redisRenderingQueue->numberOfQueuedJobs($contentReleaseIdentifier);
-                    $jobsWorkedThroughOverLastTenSeconds = $previousRemainingJobs - $remainingJobsCount;
-                    $renderingsPerSecondDataPoints[] = $jobsWorkedThroughOverLastTenSeconds / 10;
+                    $jobsWorkedThroughSinceLastDataPoint = $previousRemainingJobs - $remainingJobsCount;
+                    $renderingsPerSecondDataPoints[] =
+                        $jobsWorkedThroughSinceLastDataPoint / $secondsSinceLastDataPoint;
 
                     $contentReleaseLogger->debug('Waiting... ', [
                         'numberOfQueuedJobs' => $remainingJobsCount,
@@ -324,6 +351,11 @@ public function renderContentRelease(
                     $this->concurrentBuildLockService->assertNoOtherContentReleaseWasStarted($contentReleaseIdentifier);
                 }
             }
+            $nodesAddedToContentRelease += $this->addReportedRenderingsToContentRelease(
+                $contentReleaseIdentifier,
+                $contentReleaseLogger,
+                null,
+            );
 
             // NOTE: we do not abort rendering inside NodeRenderer when we encounter the first error, but we try to render
             // all pages in the full iteration until we stop the content release here.
@@ -356,11 +388,156 @@ public function renderContentRelease(
 
             yield RenderingIterationCompletedEvent::create();
 
-            $contentReleaseLogger->info('Rendering iteration completed. Continuing with next iteration.');
-            // here, the rendering has completed. in the next iteration, we try to copy the
-            // nodes which have been rendered in this iteration to the content store - so we iterate over the
-            // just-rendered nodes.
-            $currentEnumeration = $nodesScheduledForRendering;
-        } while (!empty($currentEnumeration));
+            // The next iteration checks the content cache once more for every node which did not make it into the
+            // content release yet - those whose content cache entry already had holes when its rendering was
+            // reported, and any whose report went missing.
+            $currentEnumeration = array_values(array_filter(
+                $nodesScheduledForRendering,
+                fn(EnumeratedNode $enumeratedNode) => !array_key_exists(
+                    json_encode($enumeratedNode, JSON_THROW_ON_ERROR),
+                    $nodesAddedToContentRelease,
+                ),
+            ));
+            if (empty($currentEnumeration)) {
+                yield from $this->completeContentRelease(
+                    $contentReleaseIdentifier,
+                    $contentReleaseLogger,
+                    $releaseMetadata,
+                    $startTime,
+                );
+                return;
+            }
+            $contentReleaseLogger->info(sprintf(
+                'Rendering iteration completed; %d of %d rendered nodes are not in the content release yet. Continuing with next iteration.',
+                count($currentEnumeration),
+                $totalJobsCount,
+            ));
+        } while (true);
+    }
+
+    /**
+     * Simply rendering a node again does not necessarily help: if its content cache entries are still valid, the
+     * rendering is served straight from the content cache. Fusion then never processes a document-level cache
+     * segment, so {@see \Flowpack\DecoupledContentStore\Aspects\CacheUrlMappingAspect} does not write the "doc--..."
+     * mapping entry the content release needs - and the node is scheduled again, and again, until the retry limit
+     * aborts the whole release. Flushing the node's cache entries turns the re-rendering into a real rendering.
+     *
+     * This happens here and before the rendering jobs are queued: the node tag covers all dimension variants of a
+     * node, so a flush by a render worker wipes the variants other workers have just rendered.
+     *
+     * @param EnumeratedNode[] $nodesScheduledForRendering
+     */
+    private function flushContentCacheForRetry(
+        array $nodesScheduledForRendering,
+        int $iteration,
+        ContentReleaseLogger $contentReleaseLogger,
+    ): void {
+        $tags = [];
+        foreach ($nodesScheduledForRendering as $enumeratedNode) {
+            $tags[] =
+                'Node_'
+                . $this->cachingHelper->renderWorkspaceTagForContextNode(
+                    $enumeratedNode->getWorkspaceNameFromContextPath(),
+                )
+                . '_'
+                . $enumeratedNode->getNodeIdentifier();
+        }
+
+        foreach (array_unique($tags) as $tag) {
+            $contentReleaseLogger->warn(sprintf(
+                'Iteration %d: flushed %d content cache entries for tag %s before rendering its nodes again.',
+                $iteration,
+                $this->contentCache->flushByTag($tag),
+                $tag,
+            ));
+        }
+    }
+
+    private function completeContentRelease(
+        ContentReleaseIdentifier $contentReleaseIdentifier,
+        ContentReleaseLogger $contentReleaseLogger,
+        ContentReleaseMetadata $releaseMetadata,
+        int $startTime,
+    ): \Generator {
+        $contentReleaseLogger->info(sprintf(
+            'Everything rendered completely in %d seconds. Finishing RenderOrchestrator',
+            time() - $startTime,
+        ));
+
+        // The release is complete now, so this is the point where we can determine its size once. Calculating
+        // it is expensive, which is why the Backend UI relies on this stored value instead of re-calculating it.
+        $contentReleaseSize = $this->redisContentReleaseSizeService->calculateReleaseSize(
+            RedisInstanceIdentifier::primary(),
+            $contentReleaseIdentifier,
+        );
+        $contentReleaseLogger->info(sprintf('Content release size: %.2f MB', $contentReleaseSize));
+
+        // info to all renderers that we finished, and they should terminate themselves gracefully.
+        $this->redisContentReleaseService->setContentReleaseMetadata(
+            $contentReleaseIdentifier,
+            $releaseMetadata
+                ->withStatus(NodeRenderingCompletionStatus::success())
+                ->withEndTime(new \DateTimeImmutable())
+                ->withContentReleaseSize($contentReleaseSize),
+            RedisInstanceIdentifier::primary(),
+        );
+
+        // Exit successfully.
+        yield ExitEvent::createWithStatusCode(0);
+    }
+
+    /**
+     * Copies every node the render workers reported as rendered ({@see RedisRenderingQueue::reportRenderedJob()})
+     * from the content cache to the content release.
+     *
+     * This happens while the rendering iteration is still running: an editor publishing in the content module flushes
+     * content cache tags, and the longer a rendered page waits in the content cache, the likelier it is gone again -
+     * on a busy day often enough to run the release into the iteration limit.
+     *
+     * A node whose content cache entry already has holes is left alone; the next iteration schedules it again.
+     *
+     * Workers can report faster than a single orchestrator adds, so while rendering is running a deadline hands
+     * control back to the wait loop, which keeps the statistics and the concurrent release check going.
+     *
+     * @param float|null $deadline Unix timestamp (microtime) after which no further rendering is added; null for none
+     * @return array<string, true> JSON-encoded nodes which were added to the content release
+     */
+    private function addReportedRenderingsToContentRelease(
+        ContentReleaseIdentifier $contentReleaseIdentifier,
+        ContentReleaseLogger $contentReleaseLogger,
+        ?float $deadline,
+    ): array {
+        $nodesAddedToContentRelease = [];
+        while ($deadline === null || microtime(true) < $deadline) {
+            $enumeratedNode = $this->redisRenderingQueue->fetchNextRenderedJob($contentReleaseIdentifier);
+            if ($enumeratedNode === null) {
+                break;
+            }
+            $renderedDocumentFromContentCache =
+                $this->nodeRenderingExtensionManager->tryToExtractRenderingForEnumeratedNodeFromContentCache(
+                    $enumeratedNode,
+                );
+            if (!$renderedDocumentFromContentCache->isComplete()) {
+                $contentReleaseLogger->debug('Rendered node is incomplete in the content cache, it is scheduled again in the next iteration: '
+                    . $renderedDocumentFromContentCache->getIncompleteReason(), [
+                    'url' => $renderedDocumentFromContentCache->getUrl(),
+                    'node' => $enumeratedNode,
+                ]);
+                continue;
+            }
+
+            $contentReleaseLogger->debug('Node rendered, adding to content release', [
+                'url' => $renderedDocumentFromContentCache->getUrl(),
+                'node' => $enumeratedNode,
+            ]);
+            $this->nodeRenderingExtensionManager->addRenderedDocumentToContentRelease(
+                $contentReleaseIdentifier,
+                $enumeratedNode,
+                $renderedDocumentFromContentCache,
+                $contentReleaseLogger,
+            );
+            $nodesAddedToContentRelease[json_encode($enumeratedNode, JSON_THROW_ON_ERROR)] = true;
+        }
+        return $nodesAddedToContentRelease;
     }
 }