Error message "Call to a member function getUID() on null" in cron

[arnowelzel]

Steps to reproduce

1. In the Nextcloud settings set "Background jobs" to "Cron"
2. Add a cronjob for the web user with the following definition in the users crontab:
   */15 * * * * php -f /<path to nextcloud>/cron.php
3. Wait for 12-24 hours

Expected behaviour

There is no error message from cron.

Actual behaviour

There is an error message from cron: Call to a member function getUID() on null

This happens at least once a day (around 4:15 UTC or 4:30 UTC), sometimes also two or three times day.

Server configuration

Operating system: Ubuntu Linux 16.04

Web server: Apache 2.4

Database: MariaDB

PHP version: 7.0

Nextcloud version: 13.0.4

Updated from an older Nextcloud/ownCloud or fresh install: Updated

Where did you install Nextcloud from: nextcloud.com

Signing status:

Signing status

No errors have been found.

List of activated apps:

App list

Enabled:
  - activity: 2.6.1
  - apporder: 0.4.1
  - bruteforcesettings: 1.0.3
  - calendar: 1.6.1
  - caniupdate: 0.1.2
  - comments: 1.3.0
  - contacts: 2.1.5
  - dav: 1.4.7
  - deck: 0.3.1
  - defaultlinkopen: 1.0.0
  - drawio: 0.8.9
  - federatedfilesharing: 1.3.1
  - federation: 1.3.0
  - files: 1.8.0
  - files_markdown: 2.0.4
  - files_pdfviewer: 1.2.1
  - files_sharing: 1.5.0
  - files_texteditor: 2.5.1
  - files_trashbin: 1.3.0
  - files_versions: 1.6.0
  - files_videoplayer: 1.2.0
  - firstrunwizard: 2.2.1
  - gallery: 18.0.0
  - logreader: 2.0.0
  - lookup_server_connector: 1.1.0
  - news: 12.0.4
  - nextcloud_announcements: 1.2.0
  - notifications: 2.1.2
  - oauth2: 1.1.1
  - onlyoffice: 1.3.0
  - ownpad: 0.6.6
  - password_policy: 1.3.0
  - provisioning_api: 1.3.0
  - serverinfo: 1.3.0
  - sharebymail: 1.3.0
  - socialsharing_email: 1.0.3
  - spreed: 3.2.2
  - survey_client: 1.1.0
  - systemtags: 1.3.0
  - tasks: 0.9.6
  - theming: 1.4.5
  - theming_customcss: 1.0.0
  - twofactor_backupcodes: 1.2.3
  - updatenotification: 1.3.0
  - workflowengine: 1.3.0
Disabled:
  - admin_audit
  - encryption
  - files_external
  - user_external
  - user_ldap

Nextcloud configuration:

Config report

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "nextcloud.0x0c.de"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "skeletondirectory": "",
        "overwrite.cli.url": "https:\/\/nextcloud.0x0c.de",
        "dbtype": "mysql",
        "version": "13.0.4.0",
        "installed": true,
        "htaccess.RewriteBase": "\/",
        "maintenance": false,
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "knowledgebaseenabled": false,
        "theme": "",
        "loglevel": 0,
        "mysql.utf8mb4": true,
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpmode": "php",
        "mail_smtpauthtype": "LOGIN",
        "mail_domain": "***REMOVED SENSITIVE VALUE***"
    }
}

Are you using external storage, if yes which one: no

Are you using encryption: no

Are you using an external user-backend, if yes which one: no

Logs

Nextcloud log (data/nextcloud.log)

Nextcloud log

{"reqId":"UPbEBzk8rBtPtXcctU5U","level":2,"time":"2018-06-20T16:22:47+00:00","remoteAddr":"123.186.208.81","user":"--","app":"core","method":"GET","url":"\/","message":"Trusted domain error. \"123.186.208.81\" tried to access using \"46.38.230.167:443\" as host.","userAgent":"Mozilla\/5.0 (Windows NT 6.1) AppleWebKit\/537.36 (KHTML, like Gecko) Chrome\/38.0.2125.122 Safari\/537.36 SE 2.X MetaSr 1.0","version":"13.0.4.0"}
{"reqId":"FH308bGcHBnCzosfQWym","level":2,"time":"2018-06-20T16:48:33+00:00","remoteAddr":"78.129.130.47","user":"--","app":"core","method":"GET","url":"\/xmlrpc.php","message":"Trusted domain error. \"78.129.130.47\" tried to access using \"46.38.230.167\" as host.","userAgent":"Mozilla\/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.6) Gecko\/20070725 Firefox\/2.0.0.6","version":"13.0.4.0"}
{"reqId":"bSf7jWXjOLxuuF1RNWK7","level":2,"time":"2018-06-20T18:45:32+00:00","remoteAddr":"37.120.4.160","user":"--","app":"core","method":"POST","url":"\/login","message":"Login failed: 'awelzel' (Remote IP: '37.120.4.160')","userAgent":"Mozilla\/5.0 (X11; Ubuntu; Linux x86_64; rv:60.0) Gecko\/20100101 Firefox\/60.0","version":"13.0.4.0"}
{"reqId":"qfIDORhYp1pdC4BsISNW","level":2,"time":"2018-06-21T02:04:01+00:00","remoteAddr":"46.17.42.211","user":"--","app":"core","method":"GET","url":"\/","message":"Trusted domain error. \"46.17.42.211\" tried to access using \"46.38.230.167:443\" as host.","userAgent":"libwww-perl\/6.34","version":"13.0.4.0"}
{"reqId":"n3QcCBskdIwpj7rtvpDm","level":2,"time":"2018-06-21T02:09:02+00:00","remoteAddr":"141.212.122.32","user":"--","app":"core","method":"GET","url":"\/","message":"Trusted domain error. \"141.212.122.32\" tried to access using \"46.38.230.167\" as host.","userAgent":"Mozilla\/5.0 zgrab\/0.x","version":"13.0.4.0"}
{"reqId":"iBVa5YdWD5DetzuXap1Z","level":4,"time":"2018-06-21T02:15:01+00:00","remoteAddr":"","user":"--","app":"cron","method":"--","url":"--","message":"Call to a member function getUID() on null","userAgent":"--","version":"13.0.4.0"}
{"reqId":"IJOGyMN6yhfl9T9PJo7P","level":2,"time":"2018-06-21T12:29:19+00:00","remoteAddr":"107.170.255.122","user":"--","app":"core","method":"GET","url":"\/","message":"Trusted domain error. \"107.170.255.122\" tried to access using \"46.38.230.167\" as host.","userAgent":"Mozilla\/5.0 zgrab\/0.x","version":"13.0.4.0"}
{"reqId":"R0OUZ72d1NSOx4dz2yLg","level":4,"time":"2018-06-21T14:15:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"--","url":"--","message":"Call to a member function getUID() on null","userAgent":"--","version":"13.0.4.0"}

[nextcloud-bot]

GitMate.io thinks possibly related issues are #6706 (Call to a member function getUID() on null), #6803 (Nextcloud 12 throwing fatal error: cron - “Call to a member function getFileInfo() on null”), #3110 (PROPFIND causes Error: Call to a member function getCache() on null), #9476 (cron: Call to getLogger() on null in lib/public/Util.php:158), and #8047 (Call to a member function instanceOfStorage() on null in nextcloud/apps/files_sharing/lib/Cache.php:80).

[MorrisJobke]

Weird - this looks like old logs, because there is no stack trace, but https://github.com/nextcloud/server/pull/7820/files was ported to stable13 already 🤔

Could you check the last 10 lines of cron.php and comment here what is in there?

[arnowelzel]

These are the last 10 lines of cron.php of the affected instance. The file was last touched 2018-06-12 09:34 UTC when I updated to 13.0.4 with the browser based updater:

	// Log the successful cron execution
	\OC::$server->getConfig()->setAppValue('core', 'lastcron', time());
	exit();

} catch (Exception $ex) {
	\OCP\Util::writeLog('cron', $ex->getMessage(), \OCP\Util::FATAL);
} catch (Error $ex) {
	\OCP\Util::writeLog('cron', $ex->getMessage(), \OCP\Util::FATAL);
}

[arnowelzel]

If I add the changes from https://github.com/nextcloud/server/pull/7820/files to my NextCloud instance, would this prevent future updates because of some integrity checks?

[MorrisJobke]

Somehow #7820 was merged against master 😑

Okay - could you add the changes from #7820 and apply them to the cron.php manually. Then the next error message should be a lot more helpful. In the meanwhile I will backport #7820 to the next stable13 release.

[arnowelzel]

Ok, I just applied #7820 to my instance. As soon as I get a more detailed log entry, I'll post it here.

[arnowelzel]

Now I got more details. It seems there is a problem with the "Deck" app:

{"reqId":"wTluiiyXFYOnJ40fuQ3E","level":3,"time":"2018-06-22T14:15:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"--","url":"--","message":"Exception: {\"Exception\":\"Error\",\"Message\":\"Call to a member function getUID() on null\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/clients\\\/client1\\\/web28\\\/web\\\/apps\\\/deck\\\/lib\\\/Notification\\\/NotificationHelper.php(82): OCA\\\\Deck\\\\Service\\\\PermissionService->findUsers('2')\\n#1 \\\/var\\\/www\\\/clients\\\/client1\\\/web28\\\/web\\\/apps\\\/deck\\\/lib\\\/Cron\\\/ScheduledNotifications.php(55): OCA\\\\Deck\\\\Notification\\\\NotificationHelper->sendCardDuedate(Object(OCA\\\\Deck\\\\Db\\\\Card))\\n#2 \\\/var\\\/www\\\/clients\\\/client1\\\/web28\\\/web\\\/lib\\\/private\\\/BackgroundJob\\\/Job.php(61): OCA\\\\Deck\\\\Cron\\\\ScheduledNotifications->run(NULL)\\n#3 \\\/var\\\/www\\\/clients\\\/client1\\\/web28\\\/web\\\/cron.php(123): OC\\\\BackgroundJob\\\\Job->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#4 {main}\",\"File\":\"\\\/var\\\/www\\\/clients\\\/client1\\\/web28\\\/web\\\/apps\\\/deck\\\/lib\\\/Service\\\/PermissionService.php\",\"Line\":198}","userAgent":"--","version":"13.0.4.0"}

The stack trace more readable:

0. /var/www/clients/client1/web28/web/apps/deck/lib/Notification/NotificationHelper.php - line 82:  OCA\Deck\Service\PermissionService->findUsers('2')
1. /var/www/clients/client1/web28/web/apps/deck/lib/Cron/ScheduledNotifications.php - line 55:  OCA\Deck\Notification\NotificationHelper->sendCardDuedate(Object(OCA\Deck\Db\Card))
2. /var/www/clients/client1/web28/web/lib/private/BackgroundJob/Job.php - line 61:  OCA\Deck\Cron\ScheduledNotifications->run(NULL)
3. /var/www/clients/client1/web28/web/cron.php - line 123:  OC\BackgroundJob\Job->execute(Object(OC\BackgroundJob\JobList), Object(OC\Log))
4. {main}

[arnowelzel]

After checking the database I think I understand what happened.

First there was a user who created two boards. Later this user got deleted, but not the boards. So the boards became orphaned and the call of $this->permissionService->findUsers($boardId) in /apps/deck/lib/Notification/NotificationHelper.php does not find any users and returns NULL.

Is there a hook for apps to cleanup data of users when a user gets deleted?

BTW: Allowing apps to create their own database tables is at least daring - nobody can guarantee that the table names are unique. Is there a formal process to register the names in a central registry so there will not be any conflicts?

[arnowelzel]

Note to self: RTFM ;-)

https://docs.nextcloud.com/server/13/developer_manual/app/hooks.html

It seems, Deck is lacking user deleting hooks and therefore it can happen, that orphaned boards remain in the database when deleting a user in Nextcloud.

Since I cleaned up the database tables of the Deck app, the error did not occur again. So I can close this issue here.