[Bug]: Wrong user name in log for system events

[ruedigerkupper]

⚠️ 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.
• I agree to follow Nextcloud's Code of Conduct.

Bug description

We deploy NC at a school. Last night our teachers received an email notification stating they had been added to the group "teachers" by a certain user. This user was a seventh-grade pupil. Naturally, pupils are unprivileged users who could never have initiated this event. However, the message that a seventh-grade pupil apparently had the power of adding users to the "teachers" group caused … considerable concern among teachers.

Analysis

Checking the nextcloud/auditing log revealed that the respective user is actually listed as the initiating user for all kinds of "system events", such as old file versions having been deleted. This is clearly wrong.
The wrong username is not randomly picked, it's the name of the alphabetically first known user (who happens to be that seventh-grade pupil in our case). So users who should receive the notifiaction "An administrator has added you to the group …" instead receive "[wrong-username] has added you to the group …".

I remember that notifications were correct in the past, this bug must have been introduced with one of the later updates to NC 22. We are unable to upgrade at this moment, so I cannot be sure if it is present in NC 23.

Steps to reproduce

unclear

Expected behavior

logs (and notifications) have "an administrator" for system events, not the name of the alphabetically first known user.

Installation method

Manual installation

Operating system

Linux (Ubuntu Server)

PHP engine version

PHP 7.4

Web server

Apache (supported)

Database engine version

MariaDB

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?

No.

What user-backends are you using?

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

Configuration report

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "overwrite.cli.url": "https:\/\/cloud.kg-fds.de\/",
        "overwriteprotocol": "https",
        "htaccess.RewriteBase": "\/",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "10.16.112.16",
            "cloud.kg-fds.de",
            "nextcloud.kg-fds.de"
        ],
        "trusted_proxies": "***REMOVED SENSITIVE VALUE***",
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "mysql",
        "version": "22.2.6.2",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbport": "",
        "dbtableprefix": "oc_",
        "mysql.utf8mb4": true,
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "ldapProviderFactory": "OCA\\User_LDAP\\LDAPProviderFactory",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpmode": "smtp",
        "mail_sendmailmode": "smtp",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpauth": 1,
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "25",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "default_locale": "de_DE",
        "default_language": "de",
        "app_install_overwrite": [
            "ldaporg",
            "files_external_onedrive",
            "auto_mail_accounts",
            "ldapcontacts"
        ],
        "maintenance": false,
        "memcache.distributed": "\\OC\\Memcache\\Redis",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "memcache.local": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 0
        },
        "skeletondirectory": "data\/skeleton-kepler",
        "theme": "",
        "loglevel": 2,
        "sharing.enable_share_mail": false,
        "default_phone_region": "DE",
        "log.condition": {
            "apps": [
                "admin_audit"
            ]
        }
    }
}

List of activated Apps

Enabled:
  - accessibility: 1.8.0
  - activity: 2.15.0
  - admin_audit: 1.12.0
  - appointments: 1.12.2
  - apporder: 0.15.0
  - auto_groups: 1.4.0
  - bbb: 2.2.0
  - bookmarks: 10.2.1
  - calendar: 3.2.2
  - circles: 22.3.0
  - cloud_federation_api: 1.5.0
  - comments: 1.12.0
  - contacts: 4.1.0
  - dashboard: 7.2.0
  - dav: 1.20.0
  - external: 3.9.0
  - extract: 1.3.3
  - federatedfilesharing: 1.12.0
  - files: 1.17.0
  - files_downloadactivity: 1.12.0
  - files_external: 1.13.1
  - files_pdfviewer: 2.3.1
  - files_rightclick: 1.1.0
  - files_sharing: 1.14.0
  - files_texteditor: 2.14.0
  - files_trashbin: 1.12.0
  - files_versions: 1.15.0
  - files_videoplayer: 1.11.0
  - groupfolders: 10.0.2
  - logreader: 2.7.0
  - lookup_server_connector: 1.10.0
  - maps: 0.1.10
  - nextcloud_announcements: 1.11.0
  - notes: 4.3.1
  - notifications: 2.10.1
  - oauth2: 1.10.0
  - password_policy: 1.12.0
  - passwords: 2021.12.20
  - photos: 1.4.0
  - provisioning_api: 1.12.0
  - recommendations: 1.1.0
  - richdocuments: 4.2.5
  - serverinfo: 1.12.0
  - settings: 1.4.0
  - sharebymail: 1.12.0
  - spreed: 12.2.4
  - support: 1.5.0
  - text: 3.3.1
  - theming: 1.13.0
  - twofactor_backupcodes: 1.11.0
  - updatenotification: 1.12.0
  - user_ldap: 1.12.2
  - viewer: 1.6.0
  - weather_status: 1.2.0
  - welcome: 1.0.1
  - workflowengine: 2.4.0
Disabled:
  - audioplayer: 3.3.0
  - bruteforcesettings: 2.3.0
  - contactsinteraction: 1.3.0
  - encryption
  - federation: 1.12.0
  - files_mindmap: 0.0.26
  - firstrunwizard: 2.11.0
  - integration_moodle: 1.0.2
  - integration_onedrive: 1.1.2
  - integration_twitter: 1.0.2
  - integration_whiteboard: 0.0.14
  - jitsi: 0.14.0
  - ldap_contacts_backend: 1.2.0
  - ldapcontacts: 2.0.5
  - mail: 1.11.7
  - music: 1.5.1
  - privacy: 1.6.0
  - survey_client: 1.10.0
  - systemtags: 1.12.0
  - tasks: 0.14.4
  - user_status: 1.1.1
  - workflow_pdf_converter: 1.7.0

Nextcloud Signing status

No errors have been found.

Nextcloud Logs

One example entry:

{"reqId":"rLbKjg96GHmAtb12QjqX","level":1,"time":"2022-04-06T12:21:12+00:00","remoteAddr":"","user":"<***name of pupil removed***>","app":"admin_audit","method":"","url":"--","message":"File \"/files_trashbin/files/Demo-DB 2022-02-07 2022-02-24.ttdbx.d1649011768\" deleted from trash bin.","userAgent":"--","version":"22.2.6.2"}

Additional info

No response

[szaimen]

cc @nextcloud/security

[ruedigerkupper]

Further information:
The wrong user is an LDAP user. "teachers" is an LDAP group.

[ruedigerkupper]

I don't believe the user actually gained administrator privileges, but the log entries are wrong.

[blizzz]

@ruedigerkupper are your background jobs run per ajax, or cron? (check basic settings)

[ruedigerkupper]

cron

[blizzz]

I don't see it happening on 23 at least and am not aware of any other reports either. @come-nc maybe?

[ruedigerkupper]

Don't know if it's related. I see regular messages like this in the log:

{"reqId":"JP2c5vxUZqDgWTJ1knNb","level":2,"time":"2022-03-24T10:20:23+00:00","remoteAddr":"","user":"--","app":"files","method":"","url":"--","message":"User kup still has unscanned files after running background scan, background scan might be stopped prematurely","userAgent":"--","version":"22.2.5.1"}

Some of them have the user field set to "--" (which is probably the right value), others have the user-field set to the unprivileged user as described above. There is no conceivable pattern.

[ruedigerkupper]

Like e.g.

{"reqId":"q8rZFdpAZScNfmpqtj2g","level":2,"time":"2022-03-27T21:32:15+00:00","remoteAddr":"","user":"<***name of pupil removed***>","app":"files","method":"","url":"--","message":"User kup still has unscanned files after running background scan, background scan might be stopped prematurely","userAgent":"--","version":"22.2.5.1"}

Looks like the same message, but user keeps changing between "--" and "[pupil]" randomly.

[ruedigerkupper]

Just a very wild guess: Do administrators usually get listed at the very front of the user list? Somehow, the alphabetically first user keeps dropping in for "administrator".

[ruedigerkupper]

More wild guessing: The problem could be in the LDAP interface. All of our ~1000 users get imported through LDAP. There are just two users in the local database: one test user and me, the admin. My admin user name starts with "ak", also at the front of the alphabet.

[nickvergessen]

URL is -- so I assume it's some background job or something?

[ruedigerkupper]

Most probably the regular cron job.

[tacruc]

Could it be related to: nextcloud/activity#784

[nickvergessen]

Could have the same root cause (cron executing) but one is about admin_audit the other one is about activity.

[ruedigerkupper]

Looks similar, at least. I'll check our oc_activity table and see if it has similar messages.

[doc75]

I am the creator of nextcloud/activity#784 and it appears that the wrong user, reported as doing the action he cannot do, is the first in alphabetical order on my nextcloud instance.
I am not having user from LDAP, they are all local users.
I am also using the cron background job.
The 2 issues seems to have some similarities at least.

[kaiyou]

We are observing and investigating similar behavior across multiple Nextcloud instances ran by distinct teams.

Here are some details :

• we noticed the issue after upgrading to 23, although generated activity dates back before (while running 22.2.6 to be precise), so we simply assumed it was already there and unnoticed until more recently,
• we have strong evidence that the activity is actually misattributed and not generated by a misbehaving user,
• we have noticed both calendar and contacts activity, mostly calendar obejct deletion (object_delete_event) and card updates (card_update),
• we identified two users generating misattributed activity, one of which is first by alphabetical order and the other is... simingly random at this point,
• these two users are also misattributed in system logs (especially cron logs), during the same time frame,
• we studied the diff between 22.2.6 and 23, plus the commit log and nothing obvious popped, the bug looks accidently fixed.

We have a couple of SQL queries to identify activity related to this bug, the most naive and simple being looking for activity across accounts over an object that never appears in any share-related activity. This is not perfect but it matches the most obvious case, where a user is notified of activity on their calendars and contacts while neither the calendar nor the addressbook was ever shared.

select * from oc_activity where type='calendar_event' and "user" != affecteduser and object_id not in (select distinct(object_id) from oc_activity where subject like '%share%');

We will keep this issue updated as we keep investigating. We might drop the ball at some point since this seems fixed anyway, and simply advertise the possibly misattributed activity so our users do not panic while reviewing their logs.

[kaiyou]

After investigating a bit more, and still relating to nextcloud/activity#784, we were able to confirme that at least 90% of the issue is due to logs or activitiy generated by cron jobs (still trying to link card updates to cron jobs, but I am confident we will) :

• system logs are mainly generated by cron jobs,
• calendar object deletions are actually trashed events being deleted by calendar background jobs after a while.

This would mean that somewhere in the course of Nextcloud 22, possibly around 22.2.6, something broke about determining the proper user for logging or generating activity when no user is actually logged in, a.k.a. during background jobs.

We are going down the rabbit hole of system logs formatting, how the user is extracted from session at some point, and what happens if no session is available. Will keep this issue updated.

[kaiyou]

Quick update: the issue is actually not fixed with Nextcloud 23, but upgrading to 23 broke cron jobs on our instance; re-enabling crons triggered the issue again.

On the bright side: it is definitely related to assigning a wrong username during background jobs, and not any authentication or other nasty bug.

[kaiyou]

Just as a follow-up from nextcloud/activity#784, the issue there is being fixed by avoiding the misattributed activity from being generated in the first place.

This still does not fix this bug related to cron jobs in general, but is a great step forward for those experiencing this the nasty way: users complaining random people are deleting stuff from their calendar.

[tkurbad]

We are having/seeing the same issue here. Our setup is also LDAP-centric and the user mentioned in the logs doesn't posess the necessary privileges.

[tkurbad]

@ruedigerkupper Do you have the LDAP extension enabled for the CLI-Version of PHP as well? That was the culprit for us.

Edit: Nevermind, this didn't solve the problem.

[ruedigerkupper]

Edit: Nevermind, this didn't solve the problem.
Pity :-). The problem is unchanged in our install, users still sporadically receive confusing messages from Nextcloud.

[ZID-TU-Graz-Collab]

We can confirm this issue with PHP 8.0, Nextcloud 24.0.4 and LDAP usage

[szaimen]

Hi, please update to at least 23.0.12 and report back if it fixes the issue. Thank you!

[nextcloud-command]

This issue has been automatically marked as stale because it has not had recent activity and seems to be missing some essential information. It will be closed if no further activity occurs. Thank you for your contributions.