server icon indicating copy to clipboard operation
server copied to clipboard

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

Open ruedigerkupper opened this issue 2 years ago • 26 comments

⚠️ This issue respects the following points: ⚠️

  • [X] This is a bug, not a question or a configuration/webserver/proxy issue.
  • [X] This issue is not already reported on Github (I've searched it).
  • [x] Nextcloud Server is up to date. See Maintenance and Release Schedule for supported versions.
  • [X] 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?

  • [X] Default user-backend (database)
  • [X] 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

ruedigerkupper avatar Apr 06 '22 15:04 ruedigerkupper

cc @nextcloud/security

szaimen avatar Apr 06 '22 15:04 szaimen

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

ruedigerkupper avatar Apr 06 '22 16:04 ruedigerkupper

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

ruedigerkupper avatar Apr 06 '22 16:04 ruedigerkupper

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

blizzz avatar Apr 06 '22 17:04 blizzz

cron

ruedigerkupper avatar Apr 06 '22 17:04 ruedigerkupper

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

blizzz avatar Apr 06 '22 17:04 blizzz

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 avatar Apr 06 '22 17:04 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 avatar Apr 06 '22 17:04 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 avatar Apr 06 '22 17:04 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.

ruedigerkupper avatar Apr 06 '22 17:04 ruedigerkupper

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

nickvergessen avatar Apr 06 '22 19:04 nickvergessen

Most probably the regular cron job.

ruedigerkupper avatar Apr 06 '22 19:04 ruedigerkupper

Could it be related to: https://github.com/nextcloud/activity/issues/784

tacruc avatar Apr 11 '22 20:04 tacruc

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

nickvergessen avatar Apr 12 '22 06:04 nickvergessen

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

ruedigerkupper avatar Apr 13 '22 10:04 ruedigerkupper

I am the creator of https://github.com/nextcloud/activity/issues/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.

doc75 avatar Apr 20 '22 21:04 doc75

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 avatar May 12 '22 09:05 kaiyou

After investigating a bit more, and still relating to https://github.com/nextcloud/activity/issues/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 avatar May 13 '22 07:05 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 avatar May 14 '22 11:05 kaiyou

Just as a follow-up from https://github.com/nextcloud/activity/issues/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.

kaiyou avatar May 18 '22 17:05 kaiyou

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 avatar Jun 20 '22 10:06 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.

tkurbad avatar Jun 20 '22 10:06 tkurbad

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

ruedigerkupper avatar Jun 20 '22 15:06 ruedigerkupper

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

ZID-TU-Graz-Collab avatar Sep 14 '22 08:09 ZID-TU-Graz-Collab

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

szaimen avatar Nov 26 '22 14:11 szaimen

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.

nextcloud-command avatar Dec 27 '22 00:12 nextcloud-command