[Bug]: Duplicate log messages in frontend and from occ log in NC29

[jmechnich]

⚠️ 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 OR Nextcloud Community Forum (I've searched it).
• Nextcloud Server is up to date. See Maintenance and Release Schedule for supported versions.
• I agree to follow Nextcloud's Code of Conduct.

Bug description

After upgrading from NC 28.0.4 to NC 29, I noticed the following:

The contents of nextcloud.log is not identical to the output of ./occ log:tail or https://server.tld/settings/admin/logging.
The browser output sorts the messages by timestamp, so the order is slightly different.

More specifically, log messages from the last two hours are duplicated (the time frame is just an estimate but apparently it is not a constant number of entries).

~$ jq -r '. | {time,message} | join(" ")' < /var/log/nextcloud/nextcloud.log | tail -8
2024-04-27T16:52:28+02:00 Transaction took 1.1706590652466s
2024-04-27T17:46:21+02:00 Error while running background job OCA\GroupFolders\BackgroundJob\ExpireGroupVersions (id: 81, arguments: null)
2024-04-27T18:46:36+02:00 Error while running background job OCA\GroupFolders\BackgroundJob\ExpireGroupVersions (id: 81, arguments: null)
2024-04-27T19:46:44+02:00 Error while running background job OCA\GroupFolders\BackgroundJob\ExpireGroupVersions (id: 81, arguments: null)

~$ sudo -u www-data /var/www/nextcloud/occ log:tail -r | jq -r '. | {time,message} | join(" ")' | tail -8
2024-04-27T16:52:28+02:00 Transaction took 1.1706590652466s
2024-04-27T17:46:21+02:00 Error while running background job OCA\GroupFolders\BackgroundJob\ExpireGroupVersions (id: 81, arguments: null)
2024-04-27T18:46:36+02:00 Error while running background job OCA\GroupFolders\BackgroundJob\ExpireGroupVersions (id: 81, arguments: null)
2024-04-27T19:46:44+02:00 Error while running background job OCA\GroupFolders\BackgroundJob\ExpireGroupVersions (id: 81, arguments: null)
2024-04-27T18:46:36+02:00 Error while running background job OCA\GroupFolders\BackgroundJob\ExpireGroupVersions (id: 81, arguments: null)
2024-04-27T19:46:44+02:00 Error while running background job OCA\GroupFolders\BackgroundJob\ExpireGroupVersions (id: 81, arguments: null)

Steps to reproduce

1. Dump last few log entries directly from logfile: jq -r '. | {time,message} | join(" ")' < nextcloud.log | tail -8
2. Dump last few log entries using occ: ./occ log:tail -r | jq -r '. | {time,message} | join(" ")' | tail -8
3. Open https://server.tld/settings/admin/logging
4. Compare

Expected behavior

Log messages in log file, printed by occ log:tail and in /settings/admin/logging are identical.

Installation method

Community Manual installation with Archive

Nextcloud Server version

29

Operating system

Debian/Ubuntu

PHP engine version

PHP 8.2

Web server

Nginx

Database engine version

MariaDB

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

Upgraded to a MAJOR version (ex. 22 to 23)

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***",
        "trusted_domains": [
            "***REMOVED SENSITIVE VALUE MANUALLY***"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "mysql",
        "version": "29.0.0.19",
        "overwrite.cli.url": "***REMOVED SENSITIVE VALUE MANUALLY***",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbport": "",
        "dbtableprefix": "oc_",
        "mysql.utf8mb4": true,
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpmode": "smtp",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpauthtype": "LOGIN",
        "mail_smtpauth": 1,
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "587",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcache.distributed": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 6379,
            "timeout": 1.5,
            "password": "***REMOVED SENSITIVE VALUE***",
            "dbindex": 0
        },
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "maintenance": false,
        "theme": "",
        "log_type": "file",
        "logfile": "\/var\/log\/nextcloud\/nextcloud.log",
        "loglevel": 2,
        "logtimezone": "Europe\/Berlin",
        "updater.release.channel": "stable",
        "app_install_overwrite": [
            "calendar",
            "groupfolders",
            "ojsxc",
            "richdocuments",
            "richdocumentscode",
            "gpxpod",
            "video_converter",
            "files_markdown",
            "impersonate",
            "drawio"
        ],
        "debug": false,
        "default_phone_region": "de",
        "mail_sendmailmode": "smtp",
        "maintenance_window_start": 1,
        "trashbin_retention_obligation": "auto, 30",
        "enable_previews": true,
        "enabledPreviewProviders": [
            "OC\\Preview\\PNG",
            "OC\\Preview\\JPEG",
            "OC\\Preview\\GIF",
            "OC\\Preview\\HEIC",
            "OC\\Preview\\BMP",
            "OC\\Preview\\XBitmap",
            "OC\\Preview\\MP3",
            "OC\\Preview\\TXT",
            "OC\\Preview\\MarkDown",
            "OC\\Preview\\OpenDocument",
            "OC\\Preview\\Krita",
            "OC\\Preview\\TIFF"
        ]
    }
}

List of activated Apps

Enabled:
  - activity: 2.21.1
  - admin_audit: 1.19.0
  - bookmarks: 13.1.3
  - bruteforcesettings: 2.9.0
  - calendar: 4.7.1
  - circles: 29.0.0-dev
  - cloud_federation_api: 1.12.0
  - collectives: 2.10.1
  - comments: 1.19.0
  - contacts: 6.0.0
  - contactsinteraction: 1.10.0
  - dav: 1.30.1
  - drawio: 3.0.2
  - federatedfilesharing: 1.19.0
  - federation: 1.19.0
  - files: 2.1.0
  - files_downloadlimit: 2.0.0
  - files_external: 1.21.0
  - files_markdown: 2.4.1
  - files_pdfviewer: 2.10.0
  - files_reminders: 1.2.0
  - files_sharing: 1.21.0
  - files_trashbin: 1.19.0
  - files_versions: 1.22.0
  - firstrunwizard: 2.18.0
  - gpxpod: 5.0.18
  - groupfolders: 16.0.6
  - impersonate: 1.16.0
  - logreader: 2.14.0
  - lookup_server_connector: 1.17.0
  - nextcloud_announcements: 1.18.0
  - notes: 4.10.0
  - notifications: 2.17.0
  - oauth2: 1.17.0
  - password_policy: 1.19.0
  - photos: 2.5.0
  - polls: 7.0.3
  - privacy: 1.13.0
  - provisioning_api: 1.19.0
  - recommendations: 2.1.0
  - related_resources: 1.4.0
  - richdocuments: 8.4.0
  - richdocumentscode: 24.4.103
  - serverinfo: 1.19.0
  - settings: 1.12.0
  - sharebymail: 1.19.0
  - spreed: 19.0.0
  - support: 1.12.0
  - survey_client: 1.17.0
  - systemtags: 1.19.0
  - text: 3.10.0
  - theming: 2.4.0
  - twofactor_backupcodes: 1.18.0
  - twofactor_totp: 11.0.0-dev
  - twofactor_webauthn: 1.4.0
  - updatenotification: 1.19.1
  - user_status: 1.9.0
  - viewer: 2.3.0
  - weather_status: 1.9.0
  - workflowengine: 2.11.0

Nextcloud Signing status

No errors have been found.

Nextcloud Logs

See description.

Additional info

The errors present in the logs are caused by a missing release update for group folders reported here.

[jmechnich]

I just realized that this might actually be an issue with https://github.com/nextcloud/logreader/...

[jmechnich]

Yeah, 32f93c2 broke stuff.
Could someone move this issue to nextcloud/logreader?

Thanks in advance and sorry for the noise!