MongoDB - Defect ID: 377330
Access Control not logging successful logins on MongoDB 3.4 Community

Info

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

Top User Comments

jefersonlucascs commented on Thu, 4 May 2017 12:53:48 +0000: 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! mark.agarunov commented on Wed, 3 May 2017 21:42:23 +0000: 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 jefersonlucascs@gmail.com commented on Fri, 28 Apr 2017 08:57:50 +0000: 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 mark.agarunov commented on Thu, 27 Apr 2017 17:45:28 +0000: 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 jefersonlucascs commented on Thu, 27 Apr 2017 11:21:07 +0000: 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. mark.agarunov commented on Wed, 26 Apr 2017 20:49:15 +0000: 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

Steps to Reproduce