search

nextcloud / server

☁️ Nextcloud server, a safe home for all your data
https://nextcloud.com
GNU Affero General Public License v3.0
26.65k stars 3.99k forks source link

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

Closed tombou closed 1 year ago

tombou commented 1 year ago

⚠️ This issue respects the following points: ⚠️

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.

Capture d’écran, le 2022-11-03 à 14 47 49

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

Capture d’écran, le 2022-11-03 à 14 47 57

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?

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 commented 1 year ago

Hi, can you share your Nextcloud logs?

tombou commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

nickvergessen commented 1 year ago

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:

hansixxxx commented 1 year ago

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

hansixxxx commented 1 year ago

So the cronjob works and only the displaying is wrong?

szaimen commented 1 year ago

So the cronjob works and only the displaying is wrong?

Basically yes