[Bug]: Background jobs not reporting good information from last execution

[tombou]

⚠️ This issue respects the following points: ⚠️

• This is a bug, not a question or a configuration/webserver/proxy issue.
• This issue is not already reported on Github (I've searched it).
• Nextcloud Server is up to date. See Maintenance and Release Schedule for supported versions.
• Nextcloud Server is running on 64bit capable CPU, PHP and OS.
• I agree to follow Nextcloud's Code of Conduct.

Bug description

I've updated some of my instances from 24.0.6 to 24.0.7 and when I go to Settings, Administration - Basic Settings, it reports that my last cron job was 12h ago. I didn't change any settings for the cron job in the crontab and I've got instances still on 24.0.6 that is reporting the last sync correctly. I've even tested the webcron manually and I got success as a response without changing the last sync time. It looks like the cron jobs are performing correctly though.

Steps to reproduce

1. Update from 24.0.6 to 24.0.7
2. Check the settings/admin page under an admin account for the last run

Expected behavior

To get the last run with a success from few seconds or few minutes ago

Installation method

Community Manual installation with Archive

Operating system

Debian/Ubuntu

PHP engine version

PHP 7.4

Web server

No response

Database engine version

MySQL

Is this bug present after an update or on a fresh install?

Updated from a minor version (ex. 22.2.3 to 22.2.4)

Are you using the Nextcloud Server Encryption module?

Encryption is Disabled

What user-backends are you using?

• Default user-backend (database)
• LDAP/ Active Directory
• SSO - SAML
• Other

Configuration report

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "mysql",
        "version": "24.0.7.1",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "logtimezone": "UTC",
        "installed": true,
        "knowledgebaseenabled": false,
        "updatechecker": false,
        "mail_smtpmode": "smtp",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "465",
        "mail_smtptimeout": 10,
        "mail_smtpauth": 1,
        "mail_smtpsecure": "ssl",
        "mail_smtpauthtype": "LOGIN",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "forcessl": true,
        "loglevel": 2,
        "maintenance": false,
        "mysql.utf8mb4": true,
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "memcache.distributed": "\\OC\\Memcache\\Redis",
        "maintenance_window_start": 1,
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 6379
        },
        "default_phone_region": "CA"
    }
}

List of activated Apps

Enabled:
  - activity: 2.16.0
  - bruteforcesettings: 2.4.0
  - cloud_federation_api: 1.7.0
  - comments: 1.14.0
  - dav: 1.22.0
  - federatedfilesharing: 1.14.0
  - files: 1.19.0
  - files_pdfviewer: 2.5.0
  - files_rightclick: 1.3.0
  - files_sharing: 1.16.2
  - files_trashbin: 1.14.0
  - files_versions: 1.17.0
  - logreader: 2.9.0
  - lookup_server_connector: 1.12.0
  - oauth2: 1.12.0
  - password_policy: 1.14.0
  - photos: 1.6.0
  - provisioning_api: 1.14.0
  - ransomware_protection: 1.14.0
  - serverinfo: 1.14.0
  - settings: 1.6.0
  - systemtags: 1.14.0
  - text: 3.5.1
  - theming: 1.15.0
  - twofactor_backupcodes: 1.13.0
  - viewer: 1.8.0
  - workflowengine: 2.6.0
Disabled:
  - accessibility: 1.6.0
  - admin_audit
  - circles: 23.1.2
  - contactsinteraction: 1.1.0
  - dashboard: 7.0.0
  - encryption
  - federation: 1.10.1
  - files_external: 1.11.1
  - files_videoplayer: 0.9.9
  - firstrunwizard: 1.1
  - nextcloud_announcements: 1.9.0
  - notifications: 2.8.0
  - privacy: 1.4.0
  - recommendations: 0.8.0
  - sharebymail: 1.10.0
  - support: 1.3.0
  - survey_client: 1.8.0
  - updatenotification: 0.2.1
  - user_ldap
  - user_status: 1.0.1
  - weather_status: 1.0.0

Nextcloud Signing status

No response

Nextcloud Logs

No response

Additional info

No response

[szaimen]

Hi, can you share your Nextcloud logs?

[tombou]

Here are the newest I've got

{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:44+00:00","remoteAddr":"","user":"--","app":"updater","method":"","url":"--","message":"\OC\Repair::step: Repair step: Add job to cleanup the bruteforce entries","userAgent":"--","version":"24.0.6.1","data":{"app":"updater"}}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:44+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"","url":"--","message":"Deprecated event type for \OC\Repair::step: Symfony\Component\EventDispatcher\GenericEvent is used","userAgent":"--","version":"24.0.6.1","data":[]}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:44+00:00","remoteAddr":"","user":"--","app":"updater","method":"","url":"--","message":"\OC\Repair::step: Repair step: Queue a one-time job to check for user uploaded certificates","userAgent":"--","version":"24.0.6.1","data":{"app":"updater"}}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:44+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"","url":"--","message":"Deprecated event type for \OC\Repair::step: Symfony\Component\EventDispatcher\GenericEvent is used","userAgent":"--","version":"24.0.6.1","data":[]}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:44+00:00","remoteAddr":"","user":"--","app":"updater","method":"","url":"--","message":"\OC\Repair::step: Repair step: Repair DAV shares","userAgent":"--","version":"24.0.6.1","data":{"app":"updater"}}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:44+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"","url":"--","message":"Deprecated event type for \OC\Repair::step: Symfony\Component\EventDispatcher\GenericEvent is used","userAgent":"--","version":"24.0.6.1","data":[]}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:44+00:00","remoteAddr":"","user":"--","app":"updater","method":"","url":"--","message":"\OC\Repair::step: Repair step: Add background job to set the lookup server share state for users","userAgent":"--","version":"24.0.6.1","data":{"app":"updater"}}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:44+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"","url":"--","message":"Deprecated event type for \OC\Repair::step: Symfony\Component\EventDispatcher\GenericEvent is used","userAgent":"--","version":"24.0.6.1","data":[]}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:44+00:00","remoteAddr":"","user":"--","app":"updater","method":"","url":"--","message":"\OC\Repair::step: Repair step: Add token cleanup job","userAgent":"--","version":"24.0.6.1","data":{"app":"updater"}}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:44+00:00","remoteAddr":"","user":"--","app":"updater","method":"","url":"--","message":"\OC\Updater::startCheckCodeIntegrity: Starting code integrity check...","userAgent":"--","version":"24.0.6.1","data":{"app":"updater"}}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:46+00:00","remoteAddr":"","user":"--","app":"updater","method":"","url":"--","message":"\OC\Updater::finishedCheckCodeIntegrity: Finished code integrity check","userAgent":"--","version":"24.0.6.1","data":{"app":"updater"}}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:46+00:00","remoteAddr":"","user":"--","app":"updater","method":"","url":"--","message":"\OC\Updater::updateEnd: Update successful","userAgent":"--","version":"24.0.7.1","data":{"app":"updater"}}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:46+00:00","remoteAddr":"","user":"--","app":"updater","method":"","url":"--","message":"\OC\Updater::maintenanceDisabled: Turned off maintenance mode","userAgent":"--","version":"24.0.7.1","data":{"app":"updater"}}
{"reqId":"uAoykgvUBKhxEzZAYLdd","level":1,"time":"2022-11-03T17:00:46+00:00","remoteAddr":"","user":"--","app":"updater","method":"","url":"--","message":"\OC\Updater::resetLogLevel: Reset log level to Error(3)","userAgent":"--","version":"24.0.7.1","data":{"app":"updater"}}

[tombou]

I have a clue about the issue. I'm able to solve it doing an operation manually. I've just removed the line "'maintenance_window_start' => 1," from my config file and the status updated! I've put back the configuration and now the value update by itself like it should do every 5 minutes

Maybe there is a sensitive task that fail or a job that block this when doing an update? Also, I haven't tested if it goes through its maintenance window if the value updates correctly afterwards. I will let an instance without modifying the config file manually to see if tomorrow it will be fine.

[tombou]

Quick update, once it hits the maintenance window, it works properly. So the bug seems to be when and maintenance_window_start is configured and the update was done before that time.

[szaimen]

@nickvergessen do sensitive cronjoba maybe not update rhe last cron value if the maintenance window is not reached?

[nickvergessen]

Well it's not about the jobs, but JobList::setLastJob is setting the config value.
But also that is not the issue here

The problem is that last_checked of time insensitive jobs is not updated when they don't run, which is totally expected.

The only reason we never saw this is that the insensitive-window is 4h hours. On our instance the time is 0am UTC (~1-2am CE(S)T). From there onwards 4h is 4-5am CE(S)T so the warning only shows after 5pm CE(S)T where I guess no one is checking the admin settings anymore (especially since it's on the Basic settings and not the Overview page).

As a quick fix we could either:

• Extend this check to ignore insensitive tasks:

  server/apps/settings/lib/Settings/Admin/Server.php

  Lines 89 to 93 in e8e0f97

  	$query = $this->connection->getQueryBuilder();
  	$query->select('last_checked')
  	->from('jobs')
  	->orderBy('last_checked', 'ASC')
  	->setMaxResults(1);

• Or we increase the time to 24h or something alike

[hansixxxx]

Same problem for me after updating to 25.0.1....
Cronjob not run since 17 hours

[hansixxxx]

So the cronjob works and only the displaying is wrong?