[SERVER-28956] Access Control not logging successful logins on MongoDB 3.4 Community Created: 25/Apr/17  Updated: 31/May/17  Resolved: 03/May/17

Status: Closed
Project: Core Server
Component/s: Admin, Security
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jeferson Lucas da Costa Santana Assignee: Mark Agarunov
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File auth_command_get_get_users.log     Text File auth_command_get_get_users_2.log     File mongod.conf     Text File mongod_log_wrong_auth.log    
Operating System: ALL
Participants:

 Description   

After adjust the verbosity of the parameter "accessControl" with the command:
'db.setLogLevel(5,"accessControl")'

The log file still not login successful login.

On mongo 3.2:
2017-04-20T15:56:06.661+0200 I ACCESS [conn16895093] Successfully authenticated as principal username on admin

On mongo 3.4:
Only unsuccessful auth like:
2017-04-25T15:07:04.478+0200 I ACCESS [conn291586] SCRAM-SHA-1 authentication failed for username on admin from client 127.0.0.1:37171 ; AuthenticationFailed: SCRAM-SHA-1 authentication failed, storedKey mismatch

So I can NOT upgrade my environment from 3.2 to 3.4 safely.

Best Regards



 Comments   
Comment by Jeferson Lucas da Costa Santana [ 04/May/17 ]

I find out the problem:

The systemctl call by default uses:
/usr/bin/mongod --quiet --config /etc/mongod.conf

After some test I changed to
/usr/bin/mongod --config /etc/mongod.conf

Procedures to chance Systemctl on Ubuntu:
Edit: /etc/systemd/system/multi-user.target.wants/mongod.service
Change: ExecStart=/usr/bin/mongod --config /etc/mongod.conf
Run: systemctl daemon-reload

And the problem was solved!

Comment by Mark Agarunov [ 03/May/17 ]

Hello jefersonlucascs,

Unfortunately I am unable to reproduce this when testing on both Ubuntu 16.04 and Debian 8.1 and matching build versions of MongoDB. I am seeing both successful and unsuccessful auth being logged as expected.

For MongoDB-related support discussion please post on the mongodb-user group or Stack Overflow with the mongodb tag. A question like this involving more discussion would be best posted on the mongodb-user group.

Thanks,
Mark

Comment by Jeferson Santana [ 28/Apr/17 ]

Thanks for the Feedback Mark, in my case the successful auth is not logging the username on those environments:

One important information:
I'm using MongoDB Community Version by repos:
Debian: deb http://repo.mongodb.org/apt/debian jessie/mongodb-org/3.4 main
Ubuntu: deb [ arch=amd64,arm64 ] http://repo.mongodb.org/apt/ubuntu xenial/mongodb-org/3.4 multiverse

Env1:

root@mongo01 /var/log/mongodb # uname -srvio
Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt25-2+deb8u3 (2016-07-02) unknown GNU/Linux
root@mongo01 /var/log/mongodb # mongo --version
MongoDB shell version v3.4.2
git version: 3f76e40c105fc223b3e5aac3e20dcd026b83b38b
OpenSSL version: OpenSSL 1.0.1t  3 May 2016
allocator: tcmalloc
modules: none
build environment:
    distmod: debian81
    distarch: x86_64
    target_arch: x86_64

env2:

santanaj@mongo02:~$ uname -srvio
Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt20-1+deb8u3 (2016-01-17) unknown GNU/Linux
santanaj@mongo02:~$ mongod --version
db version v3.4.2
git version: 3f76e40c105fc223b3e5aac3e20dcd026b83b38b
OpenSSL version: OpenSSL 1.0.1k 8 Jan 2015
allocator: tcmalloc
modules: none
build environment:
    distmod: debian81
    distarch: x86_64
    target_arch: x86_64
santanaj@mongo02:~$ 

env3:

root@mongo05:/var/log/mongodb# uname -srvio
Linux 4.8.0-46-generic #49~16.04.1-Ubuntu SMP Fri Mar 31 14:51:03 UTC 2017 x86_64 GNU/Linux
root@mongo05:/var/log/mongodb# mongod --version
db version v3.4.4
git version: 888390515874a9debd1b6c5d36559ca86b44babd
OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
allocator: tcmalloc
modules: none
build environment:
    distmod: ubuntu1604
    distarch: x86_64
    target_arch: x86_64

Example of log on Ubuntu:
one login unsuccessful and next one successful :

2017-04-28T10:51:39.477+0200 I CONTROL  [initandlisten] MongoDB starting : pid=21951 port=27017 dbpath=/var/lib/mongodb 64-bit host=mongo05.pim.prod.win.windeln-it.de
2017-04-28T10:51:39.477+0200 I CONTROL  [initandlisten] db version v3.4.4
2017-04-28T10:51:39.477+0200 I CONTROL  [initandlisten] git version: 888390515874a9debd1b6c5d36559ca86b44babd
2017-04-28T10:51:39.477+0200 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
2017-04-28T10:51:39.477+0200 I CONTROL  [initandlisten] allocator: tcmalloc
2017-04-28T10:51:39.477+0200 I CONTROL  [initandlisten] modules: none
2017-04-28T10:51:39.477+0200 I CONTROL  [initandlisten] build environment:
2017-04-28T10:51:39.477+0200 I CONTROL  [initandlisten]     distmod: ubuntu1604
2017-04-28T10:51:39.477+0200 I CONTROL  [initandlisten]     distarch: x86_64
2017-04-28T10:51:39.477+0200 I CONTROL  [initandlisten]     target_arch: x86_64
2017-04-28T10:51:39.477+0200 I CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "0.0.0.0", port: 27017 }, security: { authorization: "enabled" }, storage: { dbPath: "/var/lib/mongodb", journal: { enabled: true }, wiredTiger: { engineConfig: { cacheSizeGB: 4.0 } } }, systemLog: { destination: "file", logAppend: true, logRotate: "rename", path: "/var/log/mongodb/mongod.log", quiet: true } }
2017-04-28T10:51:39.501+0200 I -        [initandlisten] Detected data files in /var/lib/mongodb created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-04-28T10:51:39.501+0200 I STORAGE  [initandlisten] 
2017-04-28T10:51:39.501+0200 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2017-04-28T10:51:39.501+0200 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
2017-04-28T10:51:39.501+0200 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=4096M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-04-28T10:51:40.739+0200 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/var/lib/mongodb/diagnostic.data'
2017-04-28T10:51:40.739+0200 I NETWORK  [thread1] waiting for connections on port 27017
2017-04-28T10:53:27.906+0200 I NETWORK  [conn3] received client metadata from 127.0.0.1:43314 conn3: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.4.4" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
2017-04-28T10:53:27.920+0200 I ACCESS   [conn3] SCRAM-SHA-1 authentication failed for jeferson on admin from client 127.0.0.1:43314 ; AuthenticationFailed: SCRAM-SHA-1 authentication failed, storedKey mismatch
2017-04-28T10:53:35.048+0200 I NETWORK  [conn4] received client metadata from 127.0.0.1:43316 conn4: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.4.4" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
root@mongo05:/var/log/mongodb# 

The sucessfull does not apear the username.

I just tested on Community version is it possible to have differences between Community and Enterprise version about LOG verbosity aspects?

Best Regards,
Jeferson Santana

Comment by Mark Agarunov [ 27/Apr/17 ]

Hello jefersonlucascs,

Thank you for providing this information. Unfortunately, I haven't been able to reproduce the behavior you are seeing. In both MongoDB 3.2 and 3.4 I am seeing successful authentication in the logs, even with the default verbosity:

2017-04-27T13:29:54.953-0400 I CONTROL  [initandlisten] MongoDB starting : pid=31086 port=27017 dbpath=/data/db 64-bit host=markworkstation
2017-04-27T13:29:54.953-0400 I CONTROL  [initandlisten] db version v3.4.4
2017-04-27T13:29:54.953-0400 I CONTROL  [initandlisten] git version: 888390515874a9debd1b6c5d36559ca86b44babd
2017-04-27T13:29:54.953-0400 I CONTROL  [initandlisten] allocator: tcmalloc
2017-04-27T13:29:54.953-0400 I CONTROL  [initandlisten] modules: none
2017-04-27T13:29:54.953-0400 I CONTROL  [initandlisten] build environment:
2017-04-27T13:29:54.953-0400 I CONTROL  [initandlisten]     distarch: x86_64
2017-04-27T13:29:54.953-0400 I CONTROL  [initandlisten]     target_arch: x86_64
2017-04-27T13:29:54.953-0400 I CONTROL  [initandlisten] options: { processManagement: { fork: true }, security: { authorization: "enabled" }, systemLog: { destination: "file", path: "authlog" } }
2017-04-27T13:29:54.986-0400 I -        [initandlisten] Detected data files in /data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-04-27T13:29:54.986-0400 I STORAGE  [initandlisten] 
2017-04-27T13:29:54.986-0400 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2017-04-27T13:29:54.986-0400 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
2017-04-27T13:29:54.986-0400 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=15561M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-04-27T13:29:55.307-0400 I CONTROL  [initandlisten] 
2017-04-27T13:29:55.307-0400 I CONTROL  [initandlisten] 
2017-04-27T13:29:55.307-0400 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2017-04-27T13:29:55.307-0400 I CONTROL  [initandlisten] **        We suggest setting it to 'never'
2017-04-27T13:29:55.307-0400 I CONTROL  [initandlisten] 
2017-04-27T13:29:55.311-0400 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/data/db/diagnostic.data'
2017-04-27T13:29:55.311-0400 I NETWORK  [thread1] waiting for connections on port 27017
2017-04-27T13:30:12.802-0400 I NETWORK  [thread1] connection accepted from 127.0.0.1:43912 #1 (1 connection now open)
2017-04-27T13:30:12.802-0400 I NETWORK  [conn1] received client metadata from 127.0.0.1:43912 conn1: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.4.4" }, os: { type: "Linux", name: "NAME="Arch Linux"", architecture: "x86_64", version: "Kernel 4.9.11-1-ARCH" } }
2017-04-27T13:30:12.824-0400 I ACCESS   [conn1] Successfully authenticated as principal myUserAdmin on admin
2017-04-27T13:30:12.825-0400 I ACCESS   [conn1] Unauthorized: not authorized on admin to execute command { getLog: "startupWarnings" }
2017-04-27T13:30:12.826-0400 I ACCESS   [conn1] Unauthorized: not authorized on admin to execute command { replSetGetStatus: 1.0, forShell: 1.0 }
2017-04-27T13:30:15.544-0400 I -        [conn1] end connection 127.0.0.1:43912 (1 connection now open)
2017-04-27T13:30:20.312-0400 I NETWORK  [thread1] connection accepted from 127.0.0.1:43914 #2 (1 connection now open)
2017-04-27T13:30:20.312-0400 I NETWORK  [conn2] received client metadata from 127.0.0.1:43914 conn2: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.4.4" }, os: { type: "Linux", name: "NAME="Arch Linux"", architecture: "x86_64", version: "Kernel 4.9.11-1-ARCH" } }
2017-04-27T13:30:20.340-0400 I ACCESS   [conn2] SCRAM-SHA-1 authentication failed for myUserAdmin on admin from client 127.0.0.1:43914 ; AuthenticationFailed: SCRAM-SHA-1 authentication failed, storedKey mismatch
2017-04-27T13:30:20.342-0400 I -        [conn2] end connection 127.0.0.1:43914 (1 connection now open)

Also note that the Auditing functionality provided by MongoDB Enterprise, specifically the auditAuthorizationSuccess setting, would allow for substantially more detailed logging on authentication and authorization.

Thanks,
Mark

Comment by Jeferson Lucas da Costa Santana [ 27/Apr/17 ]

Complete logs from mongod - mongod_log_wrong_auth.log
Complete configuration file - mongod.conf
Command being to authenticate1 - auth_command_get_get_users.log
Command being to authenticate2 - auth_command_get_get_users_2.log

On the log I also tried to put wrong password and only then the user "santanaj" appears on the log file.

The problem is that it's important to now who open the authentication in the logs and this information is not available.

Comment by Mark Agarunov [ 26/Apr/17 ]

Hello jefersonlucascs,

Thank you for the report. To help us better understand what may be causing this behavior, please provide the following:

  • The complete logs from mongod with the systemLog verbosity set to5 when this issue is present
  • The complete configuration for mongod,
  • The exact command being used to authenticate,
  • The output of running use admin; db.getUsers() in the mongo shell.

Thanks,
Mark

Generated at Thu Feb 08 04:19:31 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.