Auto-load only new log data

This is way more complicated that just reloading the log file, but also
way nicer.

Signed-off-by: Pablo Zmdl <pablo@nextcloud.com>

php/public/index.php

@@ -11,6 +11,7 @@ ini_set('max_execution_time', '7200');
 ini_set('log_errors_max_len', '0');
 
 use DI\Container;
+use DI\NotFoundException;
 use Slim\Csrf\Guard;
 use Slim\Factory\AppFactory;
 use Slim\Views\Twig;
@@ -171,6 +172,15 @@ $app->get('/setup', function (Request $request, Response $response, array $args)
         ]
     );
 });
+$app->get('/log', function (Request $request, Response $response, array $args) use ($container) {
+    $params = $request->getQueryParams();
+    $id = $params['id'] ?? '';
+    if (!str_starts_with($id, 'nextcloud-aio-')) {
+        throw new DI\NotFoundException();
+    }
+    $view = Twig::fromRequest($request);
+    return $view->render($response, 'log.twig', ['id' => $id]);
+});
 
 // Auth Redirector
 $app->get('/', function (\Psr\Http\Message\RequestInterface $request, Response $response, array $args) use ($container) {

php/public/log-view.js

@@ -0,0 +1,142 @@
+class LogViewer {
+    // Configure the interval in seconds for autoloading log data.
+    autoloadIntervalSec = 5;
+    // Set to true to see some debug log statements in the browser console.
+    debugLog = false;
+
+    // Don't touch these, please.
+    containerId;
+    apiBaseUrl = 'api/docker/logs';
+    autoloadIntervalId = null;
+    logElem;
+    lastLogTimestamp = '';
+    autoloadingDisabledFromButton = false;
+    loaderElem;
+    dataLoadingLock;
+
+    constructor() {
+        const id = document.body.dataset.containerId;
+        if (typeof(id) !== 'string' || !id.startsWith('nextcloud-aio-')) {
+            throw new Exception('Invalid container ID');
+        }
+        this.containerId = id;
+        this.logElem = document.querySelector('pre');
+        this.loaderElem = document.querySelector('.loader');
+        this.initAutoloadingControls();
+        // Enable automatic log data loading.
+        this.startAutoloading();
+    }
+
+    startAutoloading() {
+        // Load log data immediately.
+        this.loadAndAppendLogData();
+        // Load new log data repeatedly.
+        this.debug("Starting autoloading");
+        this.autoloadIntervalId = setInterval(() => {
+            if (this.isAutoloadingEnabled()) {
+                this.loadAndAppendLogData();
+            }
+        }, 5000);
+    }
+
+    stopAutoloading() {
+        this.debug("Stopping autoloading");
+        clearInterval(this.autoloadIntervalId);
+        this.autoloadIntervalId = null;
+    }
+
+    isAutoloadingEnabled() {
+        return !!this.autoloadIntervalId;
+    }
+
+    getUrl() {
+        return `${this.apiBaseUrl}?id=${this.containerId}&since=${this.lastLogTimestamp}`;
+    }
+
+    debug(...args) {
+        if (this.debugLog) {
+            console.debug('LogViewer:', ...args);
+        }
+    }
+
+    // Load log data and append it to the DOM.
+    loadAndAppendLogData() {
+        if (this.dataLoadingLock) {
+            this.debug("Another log data loading request is still running, cancelling this request");
+            return;
+        }
+        this.debug("Loading new log data");
+        this.dataLoadingLock = true;
+        this.loaderElem.classList.remove('hidden');
+        fetch(this.getUrl())
+            .then((response) => {
+                if (!response.ok) {
+                    throw new Error("Error while fetching log data!");
+                }
+                return response;
+            })
+            .then((response) => response.text())
+            .then((text) => {
+                text = text.trim();
+                if (text.length === 0) {
+                    this.debug("Received no new log data from server");
+                    return;
+                }
+                this.debug("Received", Math.round(text.length / 1024), "KB of new log data from server");
+                this.logElem.append(text + "\n");
+                this.scrollToBottom();
+                this.lastLogTimestamp = text.split("\n").at(-1)?.split(' ')[0] ?? '';
+            })
+            .finally(() => {
+                this.dataLoadingLock = false;
+                this.loaderElem.classList.add('hidden');
+                this.debug("Finished log data loading");
+            })
+            .catch((err) => console.error(err));
+    }
+
+    scrollToBottom() {
+        window.scrollTo(0, document.body.scrollHeight);
+    }
+
+    initAutoloadingControls() {
+        // Provide a button that allows to manually disable the autoloading.
+        const button = document.getElementById('autoloading-control');
+        const statusElem = document.getElementById('autoloading-status');
+        if (!button) {
+            return;
+        }
+        button.addEventListener('click', (event) => {
+            event.preventDefault();
+            if (this.isAutoloadingEnabled()) {
+                this.stopAutoloading();
+                statusElem.textContent = 'disabled';
+                button.textContent = 'Enable';
+                this.autoloadingDisabledFromButton = true;
+            } else {
+                this.startAutoloading();
+                statusElem.textContent = 'enabled';
+                button.textContent = 'Disable';
+                this.autoloadingDisabledFromButton = false;
+            }
+        });
+
+        // Load new data immediately if the window gets visible to the user again (unless autoloading has been
+        // disabled).
+        document.addEventListener('visibilitychange', () => {
+            if (document.visibilityState === 'visible') {
+                this.debug("Window became visible");
+                if (!this.autoloadingDisabledFromButton) {
+                    this.startAutoloading();
+                }
+            } else {
+                this.debug("Window became hidden");
+                this.stopAutoloading();
+            }
+        });
+    }
+}
+
+document.addEventListener("DOMContentLoaded", () => {
+    new LogViewer();
+});

php/src/Controller/DockerController.php

@@ -11,7 +11,6 @@ use Psr\Http\Message\ResponseInterface as Response;
 use Psr\Http\Message\ServerRequestInterface as Request;
 use AIO\Data\ConfigurationManager;
 use Slim\Psr7\NonBufferedBody;
-use Slim\Views\Twig;
 
 readonly class DockerController {
     private const string TOP_CONTAINER = 'nextcloud-aio-apache';
@@ -72,13 +71,19 @@ readonly class DockerController {
             $id = $requestParams['id'];
         }
         if (str_starts_with($id, 'nextcloud-aio-')) {
-            $logs = $this->dockerActionManager->GetLogs($id);
+            $since = $this->getTimestampForDockerLogsApiSince($requestParams['since'] ?? '');
+            $logs = $this->dockerActionManager->GetLogs($id, $since);
         } else {
             $logs = 'Container not found.';
         }
 
-        $view = Twig::fromRequest($request);
-        return $view->render($response, 'log.twig', ['logContent' => $logs]);
+        $body = $response->getBody();
+        $body->write($logs);
+
+        return $response
+            ->withStatus(200)
+            ->withHeader('Content-Type', 'text/plain; charset=utf-8')
+            ->withHeader('Content-Disposition', 'inline');
     }
 
     public function StartBackupContainerBackup(Request $request, Response $response, array $args) : Response {
@@ -353,4 +358,38 @@ readonly class DockerController {
     private function getStreamingResponseHtmlEnd() : string {
         return "\n  </body>\n</html>";
     }
+
+    private function getTimestampForDockerLogsApiSince(string $input) : string
+    {
+        if ($input === '') {
+            return '';
+        }
+
+        // We expect an RFC3339Nano string with Timezone UTC here, as docker will put out.
+        // Unfortunately PHP doesn't support this format with nanoseconds, so we have to help
+        // ourselves a little bit.
+        // First we split off the nanoseconds.
+        preg_match('/^(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2})\.(\d{9}).*/', $input, $match);
+        if (count($match) !== 3) {
+            // The input doesn't match our expectations, it might be manipulated, we ignore it.
+            return '';
+        }
+
+        $datetime = \DateTimeImmutable::createFromFormat("Y-m-d\\TH:i:s", $match[1]);
+        $nanoseconds = $match[2];
+
+        if ($datetime === false) {
+            // Input was not parseable, it might be manipulated, we ignore it.
+            return '';
+        }
+
+        // Format the datetime as unix timestamp.
+        $timestamp = $datetime->format('U');
+
+        // Increase the nanoseconds by 1, so we don't get the line with exactly the original datetime again.
+        $nanoseconds = strval(intval($nanoseconds) + 1);
+
+        // Now append the nanoseconds to the timestamp-string.
+        return "{$timestamp}.{$nanoseconds}";
+    }
 }

php/src/Docker/DockerActionManager.php

@@ -145,11 +145,12 @@ readonly class DockerActionManager {
         }
     }
 
-    public function GetLogs(string $id): string {
+    public function GetLogs(string $id, string $since = ''): string {
         $url = $this->BuildApiUrl(
             sprintf(
-                'containers/%s/logs?stdout=true&stderr=true&timestamps=true',
-                urlencode($id)
+                'containers/%s/logs?stdout=true&stderr=true&timestamps=true&since=%s',
+                urlencode($id),
+                $since
             ));
         $responseBody = (string)$this->guzzleClient->get($url)->getBody();
 

php/templates/components/container-state.twig

@@ -4,15 +4,15 @@
     {% if c.GetStartingState().value == 'starting' %}
       <span class="status running"></span>
       {{ c.displayName }}
-      (<a href="api/docker/logs?id={{ c.identifier }}" target="_blank">Starting</a>)
+      (<a href="log?id={{ c.identifier }}" target="_blank">Starting</a>)
     {% elseif c.GetRunningState().value == 'running' %}
       <span class="status success"></span>
       {{ c.displayName }}
-      (<a href="api/docker/logs?id={{ c.identifier }}" target="_blank">Running</a>)
+      (<a href="log?id={{ c.identifier }}" target="_blank">Running</a>)
     {% else %}
       <span class="status error"></span>
       {{ c.displayName }}
-      (<a href="api/docker/logs?id={{ c.identifier }}" target="_blank">Stopped</a>)
+      (<a href="log?id={{ c.identifier }}" target="_blank">Stopped</a>)
     {% endif %}
     {% if c.documentation != '' %}
       (<a target="_blank" href="{{ c.documentation }}">docs</a>)
@@ -27,4 +27,4 @@
       <input type="text" value="{{ c.GetUiSecret() }}" readonly>
     </details>
   {% endif %}
-</li>
+</li>

php/templates/containers.twig

@@ -65,11 +65,11 @@
             {% endfor %}
 
             {% if is_daily_backup_running == true %}
-                <p><span class="status running"></span> Daily backup currently running. (<a href="api/docker/logs?id=nextcloud-aio-mastercontainer" target="_blank">Mastercontainer logs</a>) (<a href="api/docker/logs?id=nextcloud-aio-borgbackup" target="_blank">Borg backup container logs</a>)</p>
+                <p><span class="status running"></span> Daily backup currently running. (<a href="log?id=nextcloud-aio-mastercontainer" target="_blank">Mastercontainer logs</a>) (<a href="log?id=nextcloud-aio-borgbackup" target="_blank">Borg backup container logs</a>)</p>
                 {% if automatic_updates == true %}
                     <p>This will update your containers, the mastercontainer and, on Saturdays, your Nextcloud apps if the backup is successful.</p>
                     {% if is_mastercontainer_update_available == true %}
-                        <p>When the mastercontainer is updated it will restart, making it unavailable for a moment. (<a href="api/docker/logs?id=nextcloud-aio-watchtower" target="_blank">Logs</a>)</p>
+                        <p>When the mastercontainer is updated it will restart, making it unavailable for a moment. (<a href="log?id=nextcloud-aio-watchtower" target="_blank">Logs</a>)</p>
                     {% endif %}
                 {% endif %}
                 {% if has_update_available == false %}
@@ -80,7 +80,7 @@
                 <p><a href="" class="button reload">Reload ↻</a></p>
                 <p>If the daily backup is stuck somehow, you can unstick it by running <strong>sudo docker exec nextcloud-aio-mastercontainer rm /mnt/docker-aio-config/data/daily_backup_running</strong> and afterwards reloading this interface.</p>
             {% elseif isWatchtowerRunning == true %}
-                <p><span class="status running"></span> Mastercontainer update currently running. Once the update is complete the mastercontainer will restart, making it unavailable for a moment. Please wait until it's done. (<a href="api/docker/logs?id=nextcloud-aio-watchtower" target="_blank">Logs</a>)</p>
+                <p><span class="status running"></span> Mastercontainer update currently running. Once the update is complete the mastercontainer will restart, making it unavailable for a moment. Please wait until it's done. (<a href="log?id=nextcloud-aio-watchtower" target="_blank">Logs</a>)</p>
                 <p><a href="" class="button reload">Reload ↻</a></p>
             {% else %}
                 {% if is_backup_container_running == false and domain == "" %}
@@ -142,7 +142,7 @@
                             {% if hasBackupLocation %}
                                 {% if borg_backup_mode in ['test', 'check'] %}
                                     {% if backup_exit_code > 0 %}
-                                        <p><span class="status error"></span> Last {{ borg_backup_mode }} failed! (<a href="api/docker/logs?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
+                                        <p><span class="status error"></span> Last {{ borg_backup_mode }} failed! (<a href="log?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
                                         {% if borg_backup_mode == 'test' %}
                                             <p>Please adjust the path and/or the encryption password in order to make it work!</p>
                                         {% elseif borg_backup_mode == 'check' %}
@@ -158,7 +158,7 @@
                                             </details>
                                         {% endif %}
                                     {% elseif backup_exit_code == 0 %}
-                                        <p><span class="status success"></span> Last {{ borg_backup_mode }} successful! (<a href="api/docker/logs?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
+                                        <p><span class="status success"></span> Last {{ borg_backup_mode }} successful! (<a href="log?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
                                         {% if borg_backup_mode == 'test' %}
                                             <p>Feel free to check the integrity of the backup archive below before starting the restore process in order to make ensure that the restore will work. This can take a long time though depending on the size of the backup archive and is thus not required.</p>
                                             <form method="POST" action="api/docker/backup-check" class="xhr">
@@ -183,7 +183,7 @@
                                     {% endif %}
                                 {% elseif borg_backup_mode == 'restore' %}
                                     {% if backup_exit_code > 0 %}
-                                        <p><span class="status error"></span> Last restore failed! (<a href="api/docker/logs?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
+                                        <p><span class="status error"></span> Last restore failed! (<a href="log?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
                                         <p>The restore process has unexpectedly failed! Please adjust the path and encryption password, test it and try to restore again!</p>
                                     {% endif %}
                                 {% endif %}
@@ -228,14 +228,14 @@
 
                 {% if was_start_button_clicked == true %}
                     {% if current_channel starts with 'latest' or current_channel starts with 'beta' or current_channel starts with 'develop' %}
-                        <p>You are running the <a target="_blank" href="https://github.com/nextcloud/all-in-one#how-to-switch-the-channel"><strong>{{ current_channel }}</strong></a> channel. (<a href="api/docker/logs?id=nextcloud-aio-mastercontainer" target="_blank">Logs</a>)</p>
+                        <p>You are running the <a target="_blank" href="https://github.com/nextcloud/all-in-one#how-to-switch-the-channel"><strong>{{ current_channel }}</strong></a> channel. (<a href="log?id=nextcloud-aio-mastercontainer" target="_blank">Logs</a>)</p>
                     {% else %}
                         <p>No channel was found. This means that AIO is not able to update itself and its component and will also not be able to report about updates. Updates need to be done externally.</p>
                     {% endif %}
                 {% endif %}
 
                 {% if is_backup_container_running == true %}
-                    <p><span class="status running"></span> Backup container is currently running: {{ borg_backup_mode }} (<a href="api/docker/logs?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
+                    <p><span class="status running"></span> Backup container is currently running: {{ borg_backup_mode }} (<a href="log?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
                     <p><a href="" class="button reload">Reload ↻</a></p>
                 {% endif %}
 
@@ -401,7 +401,7 @@
                                 {% if is_backup_container_running == false %}
                                     <h2>Backup and restore</h2>
                                     {% if backup_exit_code > 0 %}
-                                        <p><span class="status error"></span> Last {{ borg_backup_mode }} failed! (<a href="api/docker/logs?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
+                                        <p><span class="status error"></span> Last {{ borg_backup_mode }} failed! (<a href="log?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
                                         {% if borg_backup_mode == "check" %}
                                             <p>The backup check was not successful. This might indicate a corrupt archive (look at the logs). If that should be the case, you can try to fix it by following <a target="_blank" href="https://borgbackup.readthedocs.io/en/stable/faq.html#i-get-an-integrityerror-or-similar-what-now"><strong>this documentation</strong></a></p>
                                             <details>
@@ -435,9 +435,9 @@
                                         {% endif %}
                                     {% elseif backup_exit_code == 0 %}
                                         {% if borg_backup_mode == "backup" %}
-                                            <p><span class="status success"></span> Last {{ borg_backup_mode }} successful on {{ last_backup_time }} UTC! (<a href="api/docker/logs?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
+                                            <p><span class="status success"></span> Last {{ borg_backup_mode }} successful on {{ last_backup_time }} UTC! (<a href="log?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
                                         {% else %}
-                                            <p><span class="status success"></span> Last {{ borg_backup_mode }} successful! (<a href="api/docker/logs?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
+                                            <p><span class="status success"></span> Last {{ borg_backup_mode }} successful! (<a href="log?id=nextcloud-aio-borgbackup" target="_blank">Logs</a>)</p>
                                         {% endif %}
                                     {% endif %}
                                 {% endif %}

php/templates/log.twig

@@ -1,45 +1,59 @@
 <html lang="en">
     <head>
+        <link rel="stylesheet" href="style.css">
         <style>
-            button {
+            body {
+                padding: 1rem;
+            }
+            #floating-box {
                 position: fixed;
                 top: 1rem;
                 right: 1rem;
-                font-size: 1.3rem;
+                width: 20rem;
+                display: flex;
+                justify-content: end;
+                align-items: center;
+            }
+            #autoloading-box {
+                display: grid;
+                gap: 0.5rem;
+                font-size: large;
+                border: solid thin gray;
+                background-color: #f9f9f9;
+                width: 10rem;
+                padding: 0.5rem 1rem;
+                margin: 0 0 0 1rem;
+            }
+            .loader {
+                opacity: 1;
+                width: 40px;
+                height: 40px;
+                align-self: inherit;
+            }
+            @starting-style {
+              .loader {
+                opacity: 0;
+              }
+            }
+            .loader.hidden {
+                display: none;
+                opacity: 0;
+                transition: opacity 1s, display 1s allow-discrete;
             }
         </style>
-        <script>
-            document.addEventListener("DOMContentLoaded", () => {
-                // Give the browser a short moment to render all text and calculate the scrollHeight, to avoid
-                // problems with scrolling to the bottom.
-                setTimeout(() => window.scrollTo(0, document.body.scrollHeight), 100);
-                // Reload after a short while if the window is visible to the user. 
-                const reloadTimer = setTimeout(() =>  {
-                    if (document.visibilityState === 'visible') {
-                        location.reload()
-                    }
-                }, 5000);
-                // Provide a button that allows to disable the reloads.
-                const button = document.querySelector('button');
-                document.querySelector('button').addEventListener('click', (event) => {
-                    event.preventDefault();
-                    clearTimeout(reloadTimer);
-                    button.disabled = true;
-                    button.textContent = 'Reloading was disabled';
-                });
-                // Reload immediately if the window gets visible to the user again (unless the
-                // no-reload-button had been clicked).
-                document.addEventListener('visibilitychange', () => {
-                    if (document.visibilityState === 'visible' && button.disabled !== true) {
-                        location.reload();
-                    }
-                });
-            });
-        </script>
+        <script src="log-view.js"></script>
     </head>
-    <body>
-        <button>Disable auto-reloading</button>
+    <body data-container-id="{{ id }}">
+        <div id="floating-box">
+            <div class="loader"></div>
+            <div id="autoloading-box">
+                <div>
+                    Automatic loading of new log data is
+                    <span id="autoloading-status">enabled</span>.
+                </div>
+                <button id="autoloading-control">Disable</button>
+            </div>
+        </div>
         <pre>{{ logContent }}</pre>
-        <div id="bottom"></div>
     </body>
 </html>