412 with every edit

[hmt]

Server issue

Detailed description in #28463 (comment)

Initial report

Describe the bug
I cannot edit markdown files. I open them, type a few characters but then the connection is lost and I have to reload, leaving the file with just a couple of characters.

To Reproduce
Steps to reproduce the behavior:

1. open Markdown file
2. start typing
3. connection gets lost

Expected behavior
I can edit as much as I like and then close the file

Screenshots

Client details:

• OS: macOS Big Sur
• Browser: Firefox
• Version: latest
• Device: desktop

Server details

Text app version: (see Nextcloud apps page)
for about three months now

Operating system:
Ubuntu

Web server:
Apache

Database:
Mysql

PHP version:
7.3

Nextcloud version: (see Nextcloud admin page)
latest 21

Logs

Nextcloud log (data/nextcloud.log)

1.2.3.4 - - [20/Apr/2021:06:28:54 +0000] "POST /apps/text/session/push HTTP/1.1" 200 961 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:54 +0000] "POST /apps/text/session/sync HTTP/1.1" 200 1208 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:55 +0000] "POST /apps/text/session/sync HTTP/1.1" 200 1141 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:55 +0000] "POST /apps/text/session/push HTTP/1.1" 200 960 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:55 +0000] "POST /apps/text/session/sync HTTP/1.1" 200 1207 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:56 +0000] "POST /apps/text/session/sync HTTP/1.1" 200 1141 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:56 +0000] "POST /apps/text/session/push HTTP/1.1" 200 1002 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:56 +0000] "POST /apps/text/session/sync HTTP/1.1" 200 1247 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:56 +0000] "POST /apps/text/session/sync HTTP/1.1" 405 979 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:56 +0000] "POST /apps/text/session/push HTTP/1.1" 200 993 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:57 +0000] "POST /apps/text/session/push HTTP/1.1" 412 882 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:57 +0000] "GET /apps/text/js/vendors~editor-collab~editor-guest.js.map?v=1234 HTTP/1.1" 200 91946 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"
1.2.3.4 - - [20/Apr/2021:06:28:58 +0000] "POST /apps/text/session/push HTTP/1.1" 412 882 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0"

and the error logs

[Tue Apr 20 06:11:46.114999 2021] [evasive20:error] [pid 586651] [client 1.2.3.4:51263] client denied by server configuration: /var/www/nextcloud/apps/dashboard/
[Tue Apr 20 06:11:46.193161 2021] [evasive20:error] [pid 586651] [client 1.2.3.4:51263] client denied by server configuration: /var/www/nextcloud/apps/dashboard/
[Tue Apr 20 06:11:46.276584 2021] [evasive20:error] [pid 586651] [client 1.2.3.4:51263] client denied by server configuration: /var/www/nextcloud/apps/dashboard/
[Tue Apr 20 06:13:28.769265 2021] [evasive20:error] [pid 586645] [client 1.2.3.4:51287] client denied by server configuration: /var/www/nextcloud/apps/text/session
[Tue Apr 20 06:13:37.637799 2021] [evasive20:error] [pid 586645] [client 1.2.3.4:51287] client denied by server configuration: /var/www/nextcloud/apps/text/session
[Tue Apr 20 06:28:56.804371 2021] [evasive20:error] [pid 587456] [client 1.2.3.4:51537] client denied by server configuration: /var/www/nextcloud/apps/text/session

Browser log

POSThttps://nextcloud.xxxl.de/apps/text/session/push [HTTP/1.1 412 Precondition failed 149ms]
failed to apply steps due to collission, retrying PollingBackend.js:223:11
    value PollingBackend.js:223
    (Async: promise callback)
    value PollingBackend.js:222
    value SyncService.js:186
    onSendable EditorWrapper.vue:322
    getSendableSteps extensions.esm.js:1490
    n extensions.esm.js:1547
    (Async: setTimeout handler)
    value extensions.esm.js:1546
    value extensions.esm.js:1503
    value tiptap.esm.js:226
    value tiptap.esm.js:226
    value tiptap.esm.js:854
    dispatch index.js:370
    focus tiptap.esm.js:752
    tt input.js:79
    someProp index.js:231
    tt input.js:77
    t input.js:43
    (Async: EventListener.handleEvent)
    t input.js:42
    Ft input.js:40
    Ft index.js:66
    value tiptap.esm.js:797
    value tiptap.esm.js:629
    n tiptap.esm.js:608
    y EditorFactory.js:99
    syncService EditorWrapper.vue:303
    (Async: promise callback)
    syncService EditorWrapper.vue:302
    value SyncService.js:297
    value SyncService.js:296
    t SyncService.js:125
    (Async: promise callback)
    t SyncService.js:124

I do have to admit it looks like an issue with Apache but I can't pinpoint it. This is my apache conf:

<IfModule mod_ssl.c>
        <VirtualHost *:80>
                ServerAdmin admin@example.com
                ServerName nextcloud.xyz.de
                RewriteEngine on
                RewriteCond %{SERVER_NAME} =nextcloud.xyz.de
                RewriteRule ^ https://%{SERVER_NAME}%{REQUEST_URI} [END,NE,R=permanent]
        </VirtualHost>
        <VirtualHost *:443>
                ServerAdmin admin@example.com
                DocumentRoot /var/www/nextcloud/
                ServerName nextcloud.xyz.de

                <IfModule mod_headers.c>
                        Header always set Strict-Transport-Security "max-age=15552000; includeSubDomains"
                </IfModule>

                <Directory /var/www/nextcloud/>
                        Options +FollowSymlinks
                        AllowOverride All
                        Require all granted
                        <IfModule mod_dav.c>
                                Dav off
                        </IfModule>
                        SetEnv HOME /var/www/nextcloud
                        SetEnv HTTP_HOME /var/www/nextcloud
                </Directory>
                ErrorLog ${APACHE_LOG_DIR}/nc.error.log
                CustomLog ${APACHE_LOG_DIR}/nc.access.log combined


                Include /etc/letsencrypt/options-ssl-apache.conf

                Define VPATH /onlyoffice
                Define DS_ADDRESS 10.1.0.236
                <Location ${VPATH}>
                        Require all granted
                        SetEnvIf Host "^(.*)$" THE_HOST=$1
                        RequestHeader setifempty X-Forwarded-Proto https
                        RequestHeader setifempty X-Forwarded-Host %{THE_HOST}e
                        RequestHeader edit X-Forwarded-Host (.*) $1${VPATH}
                        ProxyAddHeaders Off
                </Location>
                ProxyPassMatch ^\${VPATH}(.*)(\/websocket)$ "ws://${DS_ADDRESS}/$1$2"
                ProxyPass ${VPATH} "http://${DS_ADDRESS}"
                ProxyPassReverse ${VPATH} "http://${DS_ADDRESS}"

                SSLCertificateFile /etc/letsencrypt/live/nextcloud.xyz.de/fullchain.pem
                SSLCertificateKeyFile /etc/letsencrypt/live/nextcloud.xyz.de/privkey.pem
        </VirtualHost>
</IfModule>

[pasith3e]

I have a similar Issue where the connections dies after a few Minutes.
As far as I could trace it the Problem is that the CSRF Token expires.
If the app refreshes the token via a GET /csrftoken the reconnect via the button works fine.
But as far as I could find out there is no GET /csrftoken at the Opening of the file.
Once the first /csrftoken after a few Minutes and you reconnect via the button the interval for the /csrftoken call is fine and the connection is stable.

[pasith3e]

Bug was fixed for me by upgrade to Nextcloud 22.0.0.

[pReya]

Same problem for me on Nextcloud 21 (see also this forum post: https://help.nextcloud.com/t/nginx-produces-412-errors/84434/4).

[juliusknorr]

Can you share on which exact version of 21 this happens? Also is there any other request before the one that is failing? The /csrftoken refresh should happen independently from the text app and text would just reuse the token that was renewed from there on the request.

[juliusknorr]

Also if anyone can share a public link to an instance where this happens with me by mail (see my github profile), that might help to have a closer look.

[pReya]

Also if anyone can share a public link to an instance where this happens with me by mail (see my github profile), that might help to have a closer look.

It's Nextcloud 21.0.3. I will send you an E-Mail with a shared instance and a video of the bug recreation. Thanks for your answer! Hope we can get this solved.

[juliusknorr]

Thanks for that. For some reason it seems that a unrelated request (fetching one of the theming images) created a new session which will then cause the CSRF token from the initial request to be invalid for follow up requests. This all seems more like a server issue to me, though I could not reproduce anything in that regard yet locally.

From the code parts I could imagine that this line is causing the session reset

server/lib/private/Session/Internal.php

Line 58 in 215aef3

setcookie($this->invoke('session_name'), '', -1, \OC::$WEBROOT ?: '/');

so maybe you could apply the following patch to the instance, try to reproduce the issue again and then check the logs for entries containing text_debug

diff --git a/lib/private/Session/Internal.php b/lib/private/Session/Internal.php
index f02f1c2541..8fdcec841f 100644
--- a/lib/private/Session/Internal.php
+++ b/lib/private/Session/Internal.php
@@ -55,6 +55,7 @@ class Internal extends Session {
                try {
                        $this->startSession();
                } catch (\Exception $e) {
+                       \OC::$server->getLogger()->logException($e, ['app' => 'text_debug']);
                        setcookie($this->invoke('session_name'), '', -1, \OC::$WEBROOT ?: '/');
                }
                restore_error_handler();

[pReya]

@juliushaertl Thanks so much for your time! I added your log output, recreated the error and got this error in the log:

[text_debug] Error: ErrorException: session_start(): ps_files_cleanup_dir: opendir(/var/lib/php-sessions) failed: Permission denied (13) at <<closure>>

0. <<closure>>
   OC\Session\Internal->trapError(8, "session_start() ... )", "/var/www/virtua ... p", 210, {functionName: " ... e})
1. <<closure>>
   session_start({cookie_samesite: "Lax"})
2. /var/www/virtual/username/html/lib/private/Session/Internal.php line 210
   call_user_func_array("session_start", [{cookie_samesite: "Lax"}])
3. /var/www/virtual/username/html/lib/private/Session/Internal.php line 218
   OC\Session\Internal->invoke("session_start", [{cookie_samesite: "Lax"}], false)
4. /var/www/virtual/username/html/lib/private/Session/Internal.php line 57
   OC\Session\Internal->startSession()
5. /var/www/virtual/username/html/lib/base.php line 417
   OC\Session\Internal->__construct("ocfi1sfm2880")
6. /var/www/virtual/username/html/lib/base.php line 639
   OC::initSession()
7. /var/www/virtual/username/html/lib/base.php line 1076
   OC::init()
8. /var/www/virtual/username/html/index.php line 35
   require_once("/var/www/virtual/username/html/lib/base.php")

POST /apps/text/session/sync
from 2a02:8108:463f:7a34:8dc8:bb8e:eaa9:7f6e at 2021-08-17T07:35:44+00:00

I am having trouble interpreting this error message. I assume PHP sessions in general are working on my server, because it only fails occassionally. So how come it's giving this randpm permission denied error every now and then? Any explanation ideas?

[pReya]

I have changed my PHP setting session.save_path to a writable folder on my webspace (it's Uberspace, btw.) and so far everything is running smoothly. Can't tell for sure, yet – as this happened randomly. But this might have fixed it.

[juliusknorr]

Interesting, basically when PHP is doing garbage collection on the sessions on starting the session it would fail then based on the session.gc-probability value, so the fix you mentioned should work from the error trace I'm seeing. Might be worth to check back with uberspace if that is something that their default php config could be improved as I imagine that could be a general issue when the garbage collection kicks in and the save_path cannot be listed due to security restrictions on shared hosting scenarios.

[juliusknorr]

Thinking about it there is also something we can improve here on the Nextcloud side since the error when the garbage collection fails is only a E_NOTICE level which means that the session is still started properly so we could also only throw an error in case the error is actually critical, by checking the errorNumber in

server/lib/private/Session/Internal.php

Lines 183 to 185 in 215aef3

	public function trapError(int $errorNumber, string $errorString) {
	throw new \ErrorException($errorString);
	}

https://github.com/php/php-src/blob/01b3fc03c30c6cb85038250bb5640be3a09c6a32/ext/session/mod_files.c#L294

[juliusknorr]

Moving to server since it is not a text app issue itself