Cron gives errors on getQuota() on null in apps/files_versions/lib/storage.php on line 691 #23513

Closed
remkolodder opened this Issue Mar 23, 2016 · 18 comments

Projects

None yet

5 participants

@remkolodder

Steps to reproduce

  1. put this in cron: */15 * * * * www /usr/local/bin/php -f /usr/local/www/owncloud/cron.php
  2. I think this happends when file-synchronising occurs from my laptop to the server.

Expected behaviour

The cronjob runs and does it job.

Actual behaviour

The cronjob reports errors and emails them. Manually running the cron command does not lead to this issue (from cli instead of cron)

Server configuration

Operating system:
FreeBSD 10.2

Web server:
apache24-2.4.18

Database:
mysql55-server-5.5.46

PHP version:
PHP 5.6.19 (cli)

ownCloud version: (see ownCloud admin page)
ownCloud 9.0.0 (stable)

Updated from an older ownCloud or fresh install:
Updated from OC 8.2.2

Where did you install ownCloud from:
FreeBSD package

Signing status (ownCloud 9.0 and above):

No errors have been found..

List of activated apps:

Enabled:
  - activity: 2.2.1
  - calendar: 1.0
  - comments: 0.2
  - contacts: 1.0.0.0
  - dav: 0.1.5
  - external: 1.2
  - federatedfilesharing: 0.1.0
  - federation: 0.0.4
  - files: 1.4.4
  - files_external: 0.5.2
  - files_pdfviewer: 0.8
  - files_sharing: 0.9.1
  - files_texteditor: 2.1
  - files_trashbin: 0.8.0
  - files_versions: 1.2.0
  - files_videoplayer: 0.9.8
  - firstrunwizard: 1.1
  - gallery: 14.5.0
  - notifications: 0.2.3
  - provisioning_api: 0.4.1
  - systemtags: 0.2
  - templateeditor: 0.1
  - updatenotification: 0.1.0
  - user_external: 0.4
Disabled:
  - documents
  - encryption
  - mail
  - search_lucene
  - storagecharts2
  - user_ldap

The content of config/config.php:

{
    "system": {
        "instanceid": "ocmkad99mc4s",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "cloud.elvandar.org"
        ],
        "datadirectory": "\/usr\/local\/www\/owncloud\/data",
        "overwrite.cli.url": "https:\/\/cloud.elvandar.org\/owncloud",
        "dbtype": "mysql",
        "version": "9.0.0.19",
        "dbname": "evil_owncloud",
        "dbhost": "localhost:\/tmp\/mysql.sock",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "maintenance": false,
        "forcessl": true,
        "loglevel": 1,
        "log_rotate_size": "900 MiB",
        "theme": "",
        "forceSSLforSubdomains": true,
        "enable_avatars": false,
        "trashbin_retention_obligation": "10, auto",
        "updatechecker": true,
        "has_internet_connection": true,
        "redis": {
            "host": "localhost",
            "port": 6379,
            "timeout": 0,
            "dbindex": 0
        },
        "trusted_proxies": [
            "10.0.2.50"
        ],
        "forwarded_for_headers": [
            "HTTP_X_FORWARDED",
            "HTTP_FORWARDED_FOR"
        ],
        "debug": true
    }
}

Are you using external storage, if yes which one: local and nfs

Are you using encryption: /no

Are you using an external user-backend, if yes which one: LDAP/ActiveDirectory/Webdav/...
n/a

Client configuration

Browser:
Safari 9.1
Operating system:
FreeBSD 10.2

Logs

Web server error log

n/a

ownCloud log (data/owncloud.log)

{"reqId":"t4nrOVWa2nuxDZjFBMtX","remoteAddr":"2001:470:d701::500","app":"no app in context","message":"Exception: {\"Exception\":\"OCP\\\\Lock\\\\LockedException\",\"Message\":\"\\\"Fotos\\\/fotos-remko\\\/RL-Lokaal.photoslibrary\\\/Database\\\/metaSchema.db\\\" is locked\",\"Code\":0,\"Trace\":\"#0 \\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(1952): OC\\\\Files\\\\View->lockPath('\\\/files\\\/Fotos\\\/fo...', 1, false)\\n#1 \\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(799): OC\\\\Files\\\\View->lockFile('\\\/files\\\/Fotos\\\/fo...', 1)\\n#2 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/files_versions\\\/lib\\\/storage.php(192): OC\\\\Files\\\\View->copy('files\\\/\\\/Fotos\\\/fo...', 'files_versions\\\/...')\\n#3 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/files_versions\\\/lib\\\/hooks.php(60): OCA\\\\Files_Versions\\\\Storage::store('\\\/Fotos\\\/fotos-re...')\\n#4 [internal function]: OCA\\\\Files_Versions\\\\Hooks::write_hook(Array)\\n#5 \\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/hook.php(105): call_user_func(Array, Array)\\n#6 \\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/filechunking.php(211): OC_Hook::emit('OC_Filesystem', 'write', Array)\\n#7 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/connector\\\/sabre\\\/file.php(436): OC_FileChunking->file_assemble(Object(OCA\\\\Files_Trashbin\\\\Storage), 'fotos-remko\\\/mac...', '\\\/remko\\\/files\\\/Fo...')\\n#8 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/connector\\\/sabre\\\/file.php(103): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->createFileChunked(Resource id #387)\\n#9 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/connector\\\/sabre\\\/directory.php(134): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #387)\\n#10 \\\/usr\\\/local\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1036): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('metaSchema.db-c...', Resource id #387)\\n#11 \\\/usr\\\/local\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(525): Sabre\\\\DAV\\\\Server->createFile('Fotos\\\/fotos-rem...', Resource id #387, NULL)\\n#12 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#13 \\\/usr\\\/local\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#14 \\\/usr\\\/local\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(459): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#15 \\\/usr\\\/local\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(248): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#16 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php(55): Sabre\\\\DAV\\\\Server->exec()\\n#17 \\\/usr\\\/local\\\/www\\\/owncloud\\\/remote.php(138): require_once('\\\/usr\\\/local\\\/www\\\/...')\\n#18 {main}\",\"File\":\"\\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php\",\"Line\":1854}","level":3,"time":"2016-03-23T13:09:56+00:00"}
{"reqId":"P4YHGt\/acajjMNTCLjbc","remoteAddr":"","app":"files","message":" Backends provided no user object for ","level":3,"time":"2016-03-23T13:15:00+00:00"}
{"reqId":"P4YHGt\/acajjMNTCLjbc","remoteAddr":"","app":"core","message":"Error while running background job (class: OC\\Command\\CommandJob, arguments: O:33:\"OCA\\Files_Versions\\Command\\Expire\":2:{s:43:\"\u0000OCA\\Files_Versions\\Command\\Expire\u0000fileName\";s:94:\"\/Fotos\/fotos-remko\/macbook\/RL-Lokaal.photoslibrary\/resources\/recovery\/RKVersion\/0000000000.lij\";s:39:\"\u0000OCA\\Files_Versions\\Command\\Expire\u0000user\";s:5:\"remko\";}): {\"Exception\":\"OC\\\\User\\\\NoUserException\",\"Message\":\"Backends provided no user object for \",\"Code\":0,\"Trace\":\"#0 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/files_versions\\\/lib\\\/storage.php(101): OC\\\\Files\\\\Filesystem::initMountPoints(false)\\n#1 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/files_versions\\\/lib\\\/storage.php(681): OCA\\\\Files_Versions\\\\Storage::getUidAndFilename('\\\/Fotos\\\/fotos-re...')\\n#2 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/files_versions\\\/command\\\/expire.php(61): OCA\\\\Files_Versions\\\\Storage::expire('\\\/Fotos\\\/fotos-re...')\\n#3 \\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/command\\\/commandjob.php(34): OCA\\\\Files_Versions\\\\Command\\\\Expire->handle()\\n#4 \\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/backgroundjob\\\/job.php(52): OC\\\\Command\\\\CommandJob->run('O:33:\\\"OCA\\\\\\\\Files...')\\n#5 \\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/backgroundjob\\\/queuedjob.php(42): OC\\\\BackgroundJob\\\\Job->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#6 \\\/usr\\\/local\\\/www\\\/owncloud\\\/cron.php(141): OC\\\\BackgroundJob\\\\QueuedJob->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#7 {main}\",\"File\":\"\\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/filesystem.php\",\"Line\":387}","level":3,"time":"2016-03-23T13:15:00+00:00"}
{"reqId":"P4YHGt\/acajjMNTCLjbc","remoteAddr":"","app":"files","message":" Backends provided no user object for ","level":3,"time":"2016-03-23T13:15:00+00:00"}
{"reqId":"P4YHGt\/acajjMNTCLjbc","remoteAddr":"","app":"core","message":"Error while running background job (class: OC\\Command\\CommandJob, arguments: O:33:\"OCA\\Files_Versions\\Command\\Expire\":2:{s:43:\"\u0000OCA\\Files_Versions\\Command\\Expire\u0000fileName\";s:60:\"Documenten\/path/to/private/document.extension\";s:39:\"\u0000OCA\\Files_Versions\\Command\\Expire\u0000user\";s:5:\"remko\";}): {\"Exception\":\"OC\\\\User\\\\NoUserException\",\"Message\":\"Backends provided no user object for \",\"Code\":0,\"Trace\":\"#0 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/files_versions\\\/lib\\\/storage.php(101): OC\\\\Files\\\\Filesystem::initMountPoints(false)\\n#1 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/files_versions\\\/lib\\\/storage.php(681): OCA\\\\Files_Versions\\\\Storage::getUidAndFilename('Documenten\\\/docu...')\\n#2 \\\/usr\\\/local\\\/www\\\/owncloud\\\/apps\\\/files_versions\\\/command\\\/expire.php(61): OCA\\\\Files_Versions\\\\Storage::expire('Documenten\\\/docu...')\\n#3 \\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/command\\\/commandjob.php(34): OCA\\\\Files_Versions\\\\Command\\\\Expire->handle()\\n#4 \\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/backgroundjob\\\/job.php(52): OC\\\\Command\\\\CommandJob->run('O:33:\\\"OCA\\\\\\\\Files...')\\n#5 \\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/backgroundjob\\\/queuedjob.php(42): OC\\\\BackgroundJob\\\\Job->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#6 \\\/usr\\\/local\\\/www\\\/owncloud\\\/cron.php(141): OC\\\\BackgroundJob\\\\QueuedJob->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#7 {main}\",\"File\":\"\\\/usr\\\/local\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/filesystem.php\",\"Line\":387}","level":3,"time":"2016-03-23T13:15:00+00:00"}
{"reqId":"P4YHGt\/acajjMNTCLjbc","remoteAddr":"","app":"PHP","message":"Call to a member function getQuota() on null at \/usr\/local\/www\/owncloud\/apps\/files_versions\/lib\/storage.php#691","level":3,"time":"2016-03-23T13:15:00+00:00"}

Browser log

N/a.

Cron log:

PHP Fatal error:  Call to a member function getQuota() on null in /usr/local/www/owncloud/apps/files_versions/lib/storage.php on line 691
@remkolodder

@DeepDiver1975 would #23507 also resolve this issue?

Thanks!

@remkolodder

nope it does not, I patched app.php and the cron mail is still being send every 15 minutes.

@LukasReschke
Member

Regression by 3a796d1

@LukasReschke
Member

@blizzz Mind taking a look?

@LukasReschke LukasReschke added this to the 9.0.2-next-maintenance milestone Mar 24, 2016
@blizzz blizzz self-assigned this Mar 24, 2016
@PVince81 PVince81 added the sev2-high label Mar 24, 2016
@PVince81 PVince81 added the regression label Apr 19, 2016
@remkolodder

Anything I can do to get this going? Once my laptop reconnects to the local network and thus starts the sync, I get the errors.

@PVince81
Collaborator

Not sure how this can happen. Maybe the user manager did not find the user for some reason, so no quota is set ? If that's the case, the quick fix is to check for user existence.

Let me have a try.

@PVince81 PVince81 assigned PVince81 and unassigned blizzz Apr 21, 2016
@PVince81
Collaborator

I cannot reproduce the issue through normal means.

When deleting a regular user, the expire job already checks for user existence early.
For deleted LDAP users, an exception NoUserException is thrown early enough.

So the only explanation for this is a race condition where the user got deleted between the first check https://github.com/owncloud/core/blob/v9.0.1/apps/files_versions/command/expire.php#L55 and the version's call to the quota API https://github.com/owncloud/core/blob/v9.0.1/apps/files_versions/lib/storage.php#L691

I'll prepare a PR to add another check for user existence in the second location.

@PVince81
Collaborator

I tried simulating a race condition with both local users or LDAP users, but could not reproduce the issue. In both cases the user object is already cached in memory so getUser() will always succeed.

I can't find a situation where userExists would first return true and later on suddenly getUser() would return null for that same user.

Anyway, an additional check would at least prevent the error to appear and cron to abort.

@PVince81
Collaborator

Also interesting is to note that before the getUser() call there's a file_exists call which succeeds, which means the user's files still exist but the user doesn't.

@blizzz any idea what kind of twisted logic could lead to such situation ?

@PVince81
Collaborator

@remkolodder I see you're using "user_external", what user management are you using ?

@PVince81
Collaborator

Turns out the $user that is checked with userExists can be a different one than the one for expiration, which is taken from getUidAndFileName.

There is a situation where $uid can be null, it's when using a system-wide external storage. But even in that situation, the code about getQuota is never reached because it throws NoUserException early.

Weird stuff...

@PVince81
Collaborator

PR here: #24160

CC @bboule

@remkolodder

@PVince81 I am using local users only, no external management. I think only the module is enabled but not used (I tried adding it to LDAP at some point, but changed my mind given the users that might get access through that and the users that need to access this).

@PVince81
Collaborator

@remkolodder have you deleted a user recently before the problem started to appear ?
If yes, can you check if the user has an entry in the tables oc_users, oc_storages, oc_filecache (use the matching oc_storages.numeric_id for the storage)

Still trying to find how the 👻 user came to be.

@PVince81
Collaborator

Tried with a text file on a federated share, ran cron on the recipient OC: it also bails out with NoUserException in getUidAndFilename because initMountPoints is called with null, so that's also not the correct reproduction case.

@PVince81
Collaborator

HA, got it reproduced after looking into initMountPoints. You need TWO expire jobs to make it happen with a null user.

Steps:

  1. Setup two ownClouds OC_A and OC_B
  2. On OC_A, share a folder "test" with admin@OC_B
  3. As admin@OC_B, accept the share
  4. Create a text file "test/test1.txt", edit it several times to create versions
  5. Create another text file "test/test2.txt", edit it several times
  6. Check oc_jobs, there must be two version expire jobs
  7. Run cron 💥

The reason it happens: the first expire job will fail with NoUserException when calling initMountPoints. However, initMountPoints(null) will mark the null user as already initialized here https://github.com/owncloud/core/blob/v9.0.1/lib/private/files/filesystem.php#L378 and only fail later.
Then, when running the second expire job, initMountPoints(null) will not fail because the check "did we setup this user yet?" is true... So the code happily moves on with a null user.

@PVince81
Collaborator

Another test case with external storage:

  1. Setup an external storage, for example SMB, system-wide, for all users, as "/smb"
  2. Login as any user
  3. Create a file "/smb/test1.txt", edit it several times to create versions
  4. Create another file "/smb/test2.txt", edit it several times to create versions
  5. Check "oc_jobs" to make sure there are at least two version expire jobs
  6. Run cron 💥
@PVince81
Collaborator

PR is here: #24186
This should hopefully help cover more error cases than #24160.

@PVince81 PVince81 referenced this issue in owncloud/QA Apr 22, 2016
Open

Testing background jobs queue #204

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment