Transactional File Locking Does Not Work With Redis Can't Sync, Scan, or Edit Files Due to Lock

yupthatguy · May 18, 2022, 4:22am

NC24 Transactional Locking W. Redis Broken

========================

Nextcloud version (eg, 20.0.5): NC 24

Operating system and version (eg, Ubuntu 20.04): `Ubuntu 20.04

Apache or nginx version (eg, Apache 2.4.25): Apache/2.4.41

PHP version (eg, 7.4): `php7.4-fpm

The issue you are facing:

Transactional cannot be enabled with redis.

Can’t Sync Files / Can’t use files:scan with occ due to file lock / can’t edit files

Memcache / Redis correctly installed

Is this the first time you’ve seen this error? (Y/N): yes

Steps to replicate it:

Fresh install memcache / redis and NC
Attempt to share files via desktop client (ubuntu and windows clients)
attempt to use sudo -u <user> php /public_html/occ files:scan (error content below)
Attempt to edit a note in NC gui (can’t save or delete because file is locked)
Attempt to edit a fie in NC office (can’t save file, please contact your administrator)

root@admin:~# sudo -u admin php /home/admin/public_html/occ files:scan --all

Starting scan for user 1 out of 1 (randomuser)

Exception during scan: json_decode() expects parameter 1 to be string, object given

#0 [internal function]: OCA\Files\Command\Scan->exceptionErrorHandler()

#1 /home/admin/public_html/lib/private/Memcache/Redis.php(52): json_decode()

#2 /home/admin/public_html/lib/private/Memcache/Redis.php(163): OC\Memcache\Redis->get()

#3 /home/admin/public_html/lib/private/Lock/MemcacheLockingProvider.php(104): OC\Memcache\Redis->cad()

#4 /home/admin/public_html/lib/private/Files/Storage/Common.php(790): OC\Lock\MemcacheLockingProvider->releaseLock()

#5 /home/admin/public_html/lib/private/Files/Storage/Wrapper/Wrapper.php(621): OC\Files\Storage\Common->releaseLock()

#6 /home/admin/public_html/lib/private/Files/Storage/Wrapper/Wrapper.php(621): OC\Files\Storage\Wrapper\Wrapper->releaseLock()

#7 /home/admin/public_html/lib/private/Files/Cache/Scanner.php(348): OC\Files\Storage\Wrapper\Wrapper->releaseLock()

#8 /home/admin/public_html/lib/private/Files/Utils/Scanner.php(256): OC\Files\Cache\Scanner->scan()

#9 /home/admin/public_html/apps/files/lib/Command/Scan.php(144): OC\Files\Utils\Scanner->scan()

#10 /home/admin/public_html/apps/files/lib/Command/Scan.php(200): OCA\Files\Command\Scan->scanFiles()

#11 /home/admin/public_html/3rdparty/symfony/console/Command/Command.php(255): OCA\Files\Command\Scan->execute()

#12 /home/admin/public_html/core/Command/Base.php(168): Symfony\Component\Console\Command\Command->run()

#13 /home/admin/public_html/3rdparty/symfony/console/Application.php(1009): OC\Core\Command\Base->run()

#14 /home/admin/public_html/3rdparty/symfony/console/Application.php(273): Symfony\Component\Console\Application->doRunCommand()

#15 /home/admin/public_html/3rdparty/symfony/console/Application.php(149): Symfony\Component\Console\Application->doRun()

#16 /home/admin/public_html/lib/private/Console/Application.php(211): Symfony\Component\Console\Application->run()

#17 /home/admin/public_html/console.php(99): OC\Console\Application->run()

#18 /home/admin/public_html/occ(11): require_once('/home/admin/...')

#19 {main}

+---------+-------+--------------+

| Folders | Files | Elapsed time |

+---------+-------+--------------+

| 1 | 0 | 00:00:00 |

+---------+-------+--------------+

PHP Fatal error: Uncaught ErrorException: json_decode() expects parameter 1 to be string, object given in /home/admin/public_html/lib/private/Memcache/Redis.php:52

Stack trace:

#0 [internal function]: OCA\Files\Command\Scan->exceptionErrorHandler()

#1 /home/admin/public_html/lib/private/Memcache/Redis.php(52): json_decode()

#2 /home/admin/public_html/lib/private/Memcache/Redis.php(163): OC\Memcache\Redis->get()

#3 /home/admin/public_html/lib/private/Lock/MemcacheLockingProvider.php(104): OC\Memcache\Redis->cad()

#4 /home/admin/public_html/lib/private/Lock/AbstractLockingProvider.php(120): OC\Lock\MemcacheLockingProvider->releaseLock()

#5 [internal function]: OC\Lock\AbstractLockingProvider->releaseAll()

#6 {main}

thrown in /home/admin/public_html/lib/private/Memcache/Redis.php on line 52

PHP Stack trace:

PHP 1. {main}() /home/admin/public_html/occ:0

PHP 2. require_once() /home/admin/public_html/occ:11

PHP 3. OC\Console\Application->run() /home/admin/public_html/console.php:99

PHP 4. Symfony\Component\Console\Application->run() /home/admin/public_html/lib/private/Console/Application.php:211```


The output of your Nextcloud log in **Admin > Logging**:



The Admin > Logging page flashes content for a split second this becomes completely blank

The output of your config.php file in /path/to/nextcloud (make sure you remove any identifiable information!):


root@admin:~# cat /home/admin/public_html/config/config.php

<?php

$CONFIG = array (

'instanceid' => 'instance_id',

'passwordsalt' => 'password',

'secret' => 'password',

'trusted_domains' =>

array (

0 => 'www.example.com',

1 => 'example.com',

),

'datadirectory' => '/home/admin/private/data',

'dbtype' => 'mysql',

'version' => '24.0.0.12',

'overwrite.cli.url' => 'https://www.example.com',

'dbname' => 'admin',

'dbhost' => 'localhost:3306',

'dbport' => '',

'dbtableprefix' => 'oc_',

'mysql.utf8mb4' => true,

'dbuser' => 'admin',

'dbpassword' => 'password',

'installed' => true,

'memcache.local' => '\\OC\\Memcache\\Redis',

'filelocking.enabled' => true,

'memcache.locking' => '\\OC\\Memcache\\Redis',

'redis' =>

array (

'host' => 'localhost',

'port' => 6379,

'timeout' => 0.0,

'password' => 'password',

),

'default_phone_region' => 'CN',

'trashbin_retention_obligation' => '3, 7',

'mail_smtpmode' => 'smtp',

'mail_smtpsecure' => 'tls',

'mail_sendmailmode' => 'smtp',

'mail_from_address' => 'notifications',

'mail_domain' => 'example.com',

'mail_smtpauthtype' => 'PLAIN',

'mail_smtpauth' => 1,

'mail_smtphost' => 'mail.example.com',

'mail_smtpport' => '587',

'mail_smtpname' => 'notifications@example.com',

'mail_smtppassword' => 'password',

'maintenance' => false,

'loglevel' => 0,

'auth.bruteforce.protection.enabled' => 'false',

'theme' => '',

'app_install_overwrite' =>

array (

0 => 'files_antivirus',

1 => 'qownnotesapi',

2 => 'appointments',

),

'data-fingerprint' => 'fingerprint',

);

The output of your Apache/nginx/system log in /var/log/____:

Error Log

[Tue May 17 16:55:02.343368 2022] [:error] [pid 2109815] [client 123.45.678.90:43412] [client 123.45.678.90] ModSecurity: Access denied with connection close (phase 1). Operator EQ matched 0 at IP. [file "/etc/apache2/modsecurity-crs/coreruleset-3.3.2/rules/REQUEST-912-DOS-PROTECTION.conf"] [line "119"] [id "912120"] [msg "Denial of Service (DoS) attack identified from 123.45.678.90 (7 hits since last alert)"] [ver "OWASP_CRS/3.3.2"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "paranoia-level/1"] [tag "attack-dos"] [tag "OWASP_CRS"] [tag "capec/1000/210/227/469"] [hostname "example.com"] [uri "/"] [unique_id "YoNi5rIGtxGFfI5diLSZCwAAAAU"]

Access Log

123.45.678.90 - - [17/May/2022:17:33:08 +0800] "PUT /remote.php/dav/files/randomuser/Notes/notes.sqlite HTTP/1.1" 423 6277 "-" "Mozilla/5.0 (Linux) mirall/3.4.0 (build 8402) (Nextcloud, ubuntu-5.13.0-41-generic ClientArchitecture: x86_64 OsArchitecture: x86_64)"

123.45.678.90 - - [17/May/2022:17:33:08 +0800] "PUT /remote.php/dav/files/randomuser/Notes/Bug Notes/Nextcloud FilesScan bug Locking.md HTTP/1.1" 423 6309 "-" "Mozilla/5.0 (Linux) mirall/3.4.0 (build 8402) (Nextcloud, ubuntu-5.13.0-41-generic ClientArchitecture: x86_64 OsArchitecture: x86_64)"

Output errors in nextcloud.log in /var/www/ or as admin user in top right menu, filtering for errors. Use a pastebin service if necessary.

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":2,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"OC\\Log\\Rotate","method":"","url":"--","message":"Log file \"/home/admin/pr

ivate/data/nextcloud.log\" was over 104857600 bytes, moved to \"/home/admin/private/data/nextcloud.log.1\"","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OC\\Log\\Rotate job with ID 31

in 0 seconds","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

33","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

34","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

35","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

36","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

37","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

38","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Talk\\BackgroundJob\\ExpireSig

nalingMessage job with ID 38","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OCA\\Talk\\BackgroundJob\\Expi

reSignalingMessage job with ID 38 in 0 seconds","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

39","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

40","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

42","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

43","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

136","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

137","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

138","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

139","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Deck\\Cron\\ScheduledNotificat

ions job with ID 139","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OCA\\Deck\\Cron\\ScheduledNoti

fications job with ID 139 in 0 seconds","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

140","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Deck\\Cron\\CardDescriptionAct

ivity job with ID 140","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OCA\\Deck\\Cron\\CardDescripti

onActivity job with ID 140 in 0 seconds","userAgent":"--","version":"24.0.0.12"}

{"reqId":"EhNSs9UUWhkq4MVgwT6f","level":0,"time":"2022-05-18T00:05:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"CLI cron call has selected job with ID

161","userAgent":"--","version":"24.0.0.12"}

mritzmann · May 18, 2022, 6:21am

You have a WAF (Web Application Firewall) installed, which is blocking something.

As long as Nextcloud is blocked by the WAF, it cannot work.

yupthatguy · May 18, 2022, 7:17am

I have transactional locking enabled (for testing).

All of the apps below had /appinfo/app.php is deprecated in my nextcloud.log , so I disabled them.

sudo -u admin php /home/admin/public_html/occ app:disable files_antivirus extract maps metadata ncdownloader side_menu socialsharing_email timetracker transfer video_converter auto_groups

Now, nextcloud Overview says “All Checks Passed”

and logging says “No Server Logs” Every thing is working fine…

But still, I can’t sync or edit any files with transactional file locking enabled.

If I try to delete a dummy note file this appears in my logging:

[notes] Error: OCP\Lock\LockedException: "Notes/New note (2).txt" is locked, existing lock on file: 2 shared locks at <<closure>>

 0. /home/admin/public_html/lib/private/Files/View.php line 1166
    OC\Files\View->changeLock()
 1. /home/admin/public_html/lib/private/Files/View.php line 733
    OC\Files\View->basicOperation()
 2. /home/admin/public_html/lib/private/Files/Node/File.php line 131
    OC\Files\View->unlink()
 3. /home/admin/public_html/apps/notes/lib/Service/NotesService.php line 121
    OC\Files\Node\File->delete()
 4. /home/admin/public_html/apps/notes/lib/Controller/NotesController.php line 295
    OCA\Notes\Service\NotesService->delete()
 5. /home/admin/public_html/apps/notes/lib/Service/Util.php line 28
    OCA\Notes\Controller\NotesController->OCA\Notes\Controller\{closure}("*** sensitive parameters replaced ***")
 6. /home/admin/public_html/apps/notes/lib/Controller/Helper.php line 145
    OCA\Notes\Service\Util::retryIfLocked()
 7. /home/admin/public_html/apps/notes/lib/Controller/NotesController.php line 297
    OCA\Notes\Controller\Helper->handleErrorResponse()
 8. /home/admin/public_html/lib/private/AppFramework/Http/Dispatcher.php line 225
    OCA\Notes\Controller\NotesController->destroy()
 9. /home/admin/public_html/lib/private/AppFramework/Http/Dispatcher.php line 133
    OC\AppFramework\Http\Dispatcher->executeController()
10. /home/admin/public_html/lib/private/AppFramework/App.php line 172
    OC\AppFramework\Http\Dispatcher->dispatch()
11. /home/admin/public_html/lib/private/Route/Router.php line 298
    OC\AppFramework\App::main()
12. /home/admin/public_html/lib/base.php line 1023
    OC\Route\Router->match()
13. /home/admin/public_html/index.php line 36
    OC::handleRequest()

DELETE /index.php/apps/notes/notes/8590
from 114.198.189.245 by randomuser at 2022-05-18T07:03:14+00:00

However, while the above is complaining about 2 shared locks… The actual oc_files_lock table is completely empty (zero rows)…

Would love to start using NC… not just repair it… :-/

mritzmann · May 18, 2022, 7:27am

According to your log in the first post, Nextcloud is blocked by your WAF…

yupthatguy · May 19, 2022, 12:30am

@mritzmann Thanks for the feedback. While I wish modsec was the problem, that doesn’t seem to be the case.

1.) I disabled all apps throwing errors (seen above)
2.) I have whitelisted all modsec false positives
3.) Overview shows “All Checks Passed” and logging shows 0 errors.

I have currently have this in my config.php:

   'memcache.local' => '\\OC\\Memcache\\Redis',
  'filelocking.enabled' => true,
  'memcache.locking' => '\\OC\\Memcache\\APCu',

Everything works as expected. (even with random modsec errors in apps that I haven’t test yet) However, the moment that I switch to redis everything stops working as described above:

  'memcache.local' => '\\OC\\Memcache\\Redis',
  'filelocking.enabled' => true,
  'memcache.locking' => '\\OC\\Memcache\\Redis',

This is a bug. Not a WAF issue. (Now, all checks passed, No errors in log, Still can’t edit or sync files)

mritzmann · May 19, 2022, 5:44am

Have you already tested it with 127.0.0.1 and ::1? It wouldn’t be the first time that a application only resolves to IPv6, but the service behind it is only bound to the IPv4 interface.

Or the opposite.

mritzmann · May 19, 2022, 5:46am

Have you tested whether the connection to Redis works? Something like this on the console:

redis-cli -h localhost -p 6379 -a password

mritzmann · May 19, 2022, 5:49am

Does it work if you use Apc for memcache.local and Redis for memcache.locking?

yupthatguy · May 19, 2022, 5:59am

1.) I just tested with 127.0.0.1 ← does not work
2.) I disable iv6 on all of my servers
3.) redis-cli -h localhost -p 6379 -a password ← connects fine
4.)

Does it work if you use Apc for memcache.local and Redis for memcache.locking ?

I already tested this, see above… APCu works perfectly fine… the only time things break is when I use Redis:

'memcache.local' => '\\OC\\Memcache\\Redis',
(..)
'memcache.locking' => '\\OC\\Memcache\\Redis',

Hence… bug

yupthatguy · May 19, 2022, 6:05am

FYI… same problem exists on my local virtualbox test server which is identical to prod… except it doesn’t use ModSec so that I can see how applications are supposed to behave.

This is a bug.

mritzmann · May 19, 2022, 12:08pm

Maybe, Maybe not.

If you think it’s a bug, you can create an issue for it on GitHub.