Getting http error 500 as soon as I start typing

[cryptomilk]

Describe the bug
If I open a text document and start typing, I get http error 500 from the server after the first char.

I need help to further debug this. Any suggestions?

To Reproduce
Steps to reproduce the behavior:

1. Open a text file e.g. README.md
2. Start typing

Expected behavior
You are able to write text.

Client details:

• OS: openSUSE Tumbleweed
• Browser: Firefox 99

Server details

Text app version: (see Nextcloud apps page)
3.5.1

Operating system:
openSUSE 15.3

Web server:
apache2-2.4.51
php7-fpm-7.4.6

Database:
Postgresql 14

PHP version:
php 7.4.6

Nextcloud version: (see Nextcloud admin page)
24.0.0.12

Logs

Nextcloud log (data/nextcloud.log)

Nothing to find

Browser log

Insert your browser log here, this could for example include:

XHR POST https://cloud.cryptomilk.org/index.php/apps/text/session/sync
[HTTP/2 500 Internal Server Error 189ms]

	
POST
	https://cloud.cryptomilk.org/index.php/apps/text/session/sync
Status
500
Internal Server Error
VersionHTTP/2
Transferred859 B (41 B size)
Referrer Policyno-referrer

    	
    cache-control
    	no-cache, no-store, must-revalidate
    content-length
    	41
    content-security-policy
    	default-src 'none';base-uri 'none';manifest-src 'self';frame-ancestors 'none'
    content-type
    	application/json; charset=utf-8
    date
    	Thu, 05 May 2022 13:01:00 GMT
    expires
    	Thu, 19 Nov 1981 08:52:00 GMT
    feature-policy
    	autoplay 'none';camera 'none';fullscreen 'none';geolocation 'none';microphone 'none';payment 'none'
    pragma
    	no-cache
    referrer-policy
    	no-referrer
    server
    	Apache
    strict-transport-security
    	max-age=15768000; includeSubDomains
    x-content-type-options
    	nosniff
    X-Firefox-Spdy
    	h2
    x-frame-options
    	SAMEORIGIN
    x-permitted-cross-domain-policies
    	none
    x-powered-by
    	PHP/7.4.6
    x-request-id
    	0so2WU5xe32FHWhq7HSR
    x-robots-tag
    	none
    x-xss-protection
    	1; mode=block
    	
    Accept
    	application/json, text/plain, */*
    Accept-Encoding
    	gzip, deflate, br
    Accept-Language
    	en-US,en;q=0.5
    Connection
    	keep-alive
    Content-Length
    	238
    Content-Type
    	application/json
    Cookie
    	__Host-nc_sameSiteCookielax=true; __Host-nc_sameSiteCookiestrict=true; nc_username=asn; nc_token=XXXXXXXXXXXXXXX; nc_session_id=XXXXXXXXXXXX; oc_sessionPassphrase=XXXXXXXXXXXXXXXX
    DNT
    	1
    Host
    	cloud.cryptomilk.org
    Origin
    	https://cloud.cryptomilk.org
    requesttoken
    	XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
    Sec-Fetch-Dest
    	empty
    Sec-Fetch-Mode
    	cors
    Sec-Fetch-Site
    	same-origin
    Sec-GPC
    	1
    TE
    	trailers
    User-Agent
    	Mozilla/5.0 (X11; Linux x86_64; rv:99.0) Gecko/20100101 Firefox/99.0

Failed to fetch steps due to other reason Error: Request failed with status code 500
    exports createError.js:16
    exports settle.js:17
    k xhr.js:66
    exports xhr.js:78
    exports xhr.js:15
    exports dispatchRequest.js:58
    request Axios.js:112
    e Axios.js:147
    exports bind.js:9
    value PollingBackend.js:121
    setInterval handler*value PollingBackend.js:268
    value PollingBackend.js:170
    promise callback*value PollingBackend.js:131
    value PollingBackend.js:103
    value PollingBackend.js:230
    promise callback*value PollingBackend.js:227
    value SyncService.js:184
    onSendable EditorWrapper.vue:408
    t Collaboration.js:28
    v Collaboration.js:16
    setTimeout handler*85152/onCreate/this.getSendableSteps< Collaboration.js:15
    onCreate Collaboration.js:40
    emit tiptap-core.esm.js:3116
    emit tiptap-core.esm.js:3116
    dispatchTransaction tiptap-core.esm.js:3454
    dispatch index.es.js:5280
    qe index.es.js:2866
    domObserver index.es.js:3474
    flush index.es.js:3387
    observer index.es.js:3254
    at index.es.js:3243
    Vt index.es.js:3474
    Vt index.es.js:4940
    createView tiptap-core.esm.js:3401
    Ht tiptap-core.esm.js:3247
    Sn EditorFactory.js:172
PollingBackend.js:203:11

Nothing in apache error log.

[juliusknorr]

Could you check the Nextcloud log again? There should definitely be an error logged for a 500 http status.

[cryptomilk]

Ok, I finally got:

{"reqId":"701Aj8TvL98g5DFEGoK8","level":3,"time":"2022-05-06T11:02:35+00:00","remoteAddr":"2001:a61:24f8:3401:445a:9e17:40cf:237f","user":"asn","app":"text","method":"POST","url":"/index.php/apps/text/session/sync","message":"No delete permission for path","userAgent":"Mozilla/5.0 (X11; Linux x86_64; rv:99.0) Gecko/20100101 Firefox/99.0","version":"24.0.0.12","exception":{"Exception":"OCP\\Files\\NotPermittedException","Message":"No delete permission for path","Code":0,"Trace":[{"file":"/srv/www/vhosts/nextcloud/public/lib/private/Files/SimpleFS/SimpleFolder.php","line":67,"function":"delete","class":"OC\\Files\\Node\\Folder","type":"->","args":[]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/Preview/Watcher.php","line":65,"function":"delete","class":"OC\\Files\\SimpleFS\\SimpleFolder","type":"->","args":[]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/Preview/Watcher.php","line":54,"function":"deleteNode","class":"OC\\Preview\\Watcher","type":"->","args":["*** sensitive parameter replaced ***"]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/Preview/WatcherConnector.php","line":63,"function":"postWrite","class":"OC\\Preview\\Watcher","type":"->","args":["*** sensitive parameter replaced ***"]},{"function":"OC\\Preview\\{closure}","class":"OC\\Preview\\WatcherConnector","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/Hooks/EmitterTrait.php","line":106,"function":"call_user_func_array","args":[{"__class__":"Closure"},["*** sensitive parameter replaced ***"]]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/Hooks/PublicEmitter.php","line":40,"function":"emit","class":"OC\\Hooks\\BasicEmitter","type":"->","args":["\\OC\\Files","postWrite",["*** sensitive parameter replaced ***"]]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/Files/Node/Root.php","line":143,"function":"emit","class":"OC\\Hooks\\PublicEmitter","type":"->","args":["\\OC\\Files","postWrite",["*** sensitive parameter replaced ***"]]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/Files/Node/Node.php","line":117,"function":"emit","class":"OC\\Files\\Node\\Root","type":"->","args":["\\OC\\Files","postWrite",["*** sensitive parameter replaced ***"]]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/Files/Node/File.php","line":75,"function":"sendHooks","class":"OC\\Files\\Node\\Node","type":"->","args":[["postWrite"]]},{"file":"/srv/www/vhosts/nextcloud/public/apps/text/lib/Service/DocumentService.php","line":315,"function":"putContent","class":"OC\\Files\\Node\\File","type":"->","args":["This is a test! "]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/Files/Lock/LockManager.php","line":29,"function":"OCA\\Text\\Service\\{closure}","class":"OCA\\Text\\Service\\DocumentService","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/srv/www/vhosts/nextcloud/public/apps/text/lib/Service/DocumentService.php","line":316,"function":"runInScope","class":"OC\\Files\\Lock\\LockManager","type":"->","args":[{"__class__":"OCP\\Files\\Lock\\LockContext"},{"__class__":"Closure"}]},{"file":"/srv/www/vhosts/nextcloud/public/apps/text/lib/Service/ApiService.php","line":204,"function":"autosave","class":"OCA\\Text\\Service\\DocumentService","type":"->","args":["*** sensitive parameter replaced ***",40910,1,"This is a test! ",false,false,null,"/Readme.md"]},{"file":"/srv/www/vhosts/nextcloud/public/apps/text/lib/Controller/SessionController.php","line":82,"function":"sync","class":"OCA\\Text\\Service\\ApiService","type":"->","args":[40910,3796,"5tR0g2NnpvVm5dvGTlf6w4esV3D1X6oQX3Ab+NpLVmXfnO7ENwZqePDBmWrsfqGX",1,"This is a test! ",false,false]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/AppFramework/Http/Dispatcher.php","line":225,"function":"sync","class":"OCA\\Text\\Controller\\SessionController","type":"->","args":[40910,3796,"5tR0g2NnpvVm5dvGTlf6w4esV3D1X6oQX3Ab+NpLVmXfnO7ENwZqePDBmWrsfqGX",1,"This is a test! ",false,false]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/AppFramework/Http/Dispatcher.php","line":133,"function":"executeController","class":"OC\\AppFramework\\Http\\Dispatcher","type":"->","args":[{"__class__":"OCA\\Text\\Controller\\SessionController"},"sync"]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/AppFramework/App.php","line":172,"function":"dispatch","class":"OC\\AppFramework\\Http\\Dispatcher","type":"->","args":[{"__class__":"OCA\\Text\\Controller\\SessionController"},"sync"]},{"file":"/srv/www/vhosts/nextcloud/public/lib/private/Route/Router.php","line":298,"function":"main","class":"OC\\AppFramework\\App","type":"::","args":["OCA\\Text\\Controller\\SessionController","sync",{"__class__":"OC\\AppFramework\\DependencyInjection\\DIContainer"},{"_route":"text.Session.sync"}]},{"file":"/srv/www/vhosts/nextcloud/public/lib/base.php","line":1023,"function":"match","class":"OC\\Route\\Router","type":"->","args":["/apps/text/session/sync"]},{"file":"/srv/www/vhosts/nextcloud/public/index.php","line":36,"function":"handleRequest","class":"OC","type":"::","args":[]}],"File":"/srv/www/vhosts/nextcloud/public/lib/private/Files/Node/Folder.php","Line":393,"CustomMessage":"--"}}

It looks like it wants some permission it doesn't have.

ls -la Readme.md
-rw-rw----+ 1 nextcloud nextcloud 16 May  6 13:02 Readme.md

The php-fpm instance is running as the user nextcloud and it has write permissions for the file.

[cryptomilk]

I dunno what created this Readme.md. It gets automatically created by some app. I haven't found out how to turn it of.

However deleting the Readme.md and then recreating it, fixes it again.

This has something to do with the nextcloud delete permission.

[juliusknorr]

It looks like it is unable to delete the preview of that given file. Could you check if the permissions within your data/appdata_[instanceid]/previews directory are correctly set so that the nextcloud user can delete files?

[cryptomilk]

Text file previews? Isn't it faster to just read the first 200 bytes?

find appdata_*/preview -name "*.md" -type f -ls

I only see image files in the preview directory.

[juliusknorr]

No it should be an actual image file.

[DrMxxxxx]

Hi,
I have the same issue, but the error in the logs seems strange and this is a md file, which I created to test it. Because of this error the collectives app is also not working. Also strange is, that I get an 409 Error beforehand the 500 Error.
nc text logs.log

Thanks!

[cryptomilk]

I also wanted to look into the Collectives App, but it isn't functional at all, probably because of the underlying issue here ...

[juliusknorr]

Looks like an incompatibility with the backup app from the log:

  "message": "OC\\DB\\QueryBuilder\\QueryBuilder::__construct(): Argument #3 ($logger) must be of type Psr\\Log\\LoggerInterface, OC\\Log given, called in /var/www/html/custom_apps/backup/vendor/artificial-owl/my-small-php-tools/lib/Db/Nextcloud/nc23/NC23ExtendedQueryBuilder.php on line 74 in file '/var/www/html/lib/private/DB/QueryBuilder/QueryBuilder.php' line 86",

Could you check if disabling the backup app fixes that?

[juliusknorr]

Looks related: nextcloud/backup#294 nextcloud/backup#293

[DrMxxxxx]

Hi,
so. Deaktivating the Backup App solved the Problem! Amazing! :) Also the collectives app works again.

Thanks for the workaround!

[juliusknorr]

@cryptomilk Maybe you could also check that, then I'd close this here as the original issue is already tracked in the backup app.

[cryptomilk]

I don't use the Backup app and I have nothing logged in the logs. The questions remains why the one file didn't have the DELETE permissions and so Text failed but I was able to just delete the file.