[SERVER-57056] Syslog severity set incorrectly for INFO messages Created: 19/May/21  Updated: 29/Oct/23  Resolved: 12/Apr/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 4.4.6
Fix Version/s: 7.0.0-rc0, 7.1.0-rc0, 6.0.6, 4.4.22, 5.0.18

Type: Bug Priority: Major - P3
Reporter: Bouke Haarsma Assignee: Gabriel Marks
Resolution: Fixed Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Related
Assigned Teams:
Server Security
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v7.0, v6.0, v5.0, v4.4
Sprint: Security 2021-06-28, Security 2023-04-17
Participants:
Case:

 Description   

The default syslog configuration is to only output severity info or higher to /var/log/messages. I expect this would by default output slow queries as well. However this is not happening. After investigation with journalctl -p X, we discovered that slow messages have a log level of INFO, but are posted to syslog with a severity of DEBUG (7). As a result, such messages do not appear in /var/log/messages.

The documentation still mentions all messages being printed with severity info, which is not correct: https://docs.mongodb.com/manual/reference/configuration-options/#mongodb-setting-auditLog.destination: "Audit messages have a syslog severity level of info and a facility level of user."



 Comments   
Comment by Githook User [ 17/Apr/23 ]

Author:

{'name': 'Gabriel Marks', 'email': 'gabriel.marks@mongodb.com', 'username': 'marksg07'}

Message: SERVER-57056 Give LogSeverity::Log() messages syslog severity level info
Branch: v7.0
https://github.com/mongodb/mongo/commit/e4cec5692449ba0deb2c13276bd5c8c63531fed0

Comment by Githook User [ 17/Apr/23 ]

Author:

{'name': 'Gabriel Marks', 'email': 'gabriel.marks@mongodb.com', 'username': 'marksg07'}

Message: SERVER-57056 Give LogSeverity::Log() messages syslog severity level info
Branch: v6.0
https://github.com/mongodb/mongo/commit/7a07d46d278483f0d33305296d04fc9d7cbe3245

Comment by Githook User [ 17/Apr/23 ]

Author:

{'name': 'Gabriel Marks', 'email': 'gabriel.marks@mongodb.com', 'username': 'marksg07'}

Message: SERVER-57056 Give LogSeverity::Log() messages syslog severity level info
Branch: v5.0
https://github.com/mongodb/mongo/commit/b286b30653fccd7bc4ab491843abbd966fcb839a

Comment by Githook User [ 17/Apr/23 ]

Author:

{'name': 'Gabriel Marks', 'email': 'gabriel.marks@mongodb.com', 'username': 'marksg07'}

Message: SERVER-57056 Give LogSeverity::Log() messages syslog severity level info

(cherry picked from commit 851cfd2d0aaaf3ae877608236d1aad10eedd7f9e)
Branch: v4.4
https://github.com/mongodb/mongo/commit/7cb7027771c691423dddcad8d984a9c9cae8a2b0

Comment by Githook User [ 12/Apr/23 ]

Author:

{'name': 'Gabriel Marks', 'email': 'gabriel.marks@mongodb.com', 'username': 'marksg07'}

Message: SERVER-57056 Give LogSeverity::Log() messages syslog severity level info
Branch: master
https://github.com/mongodb/mongo/commit/851cfd2d0aaaf3ae877608236d1aad10eedd7f9e

Comment by Gabriel Marks [ 04/Apr/23 ]

In my investigation so far, I've noticed that while LOGV2_INFO(...) and LOGV2(...) both appear to have the same log level of {"s": "I"}, they actually have different levels under the hood (LogSeverity::Log() = 0, LogSeverity::Info() = -1). Logs with LogSeverity::Info() which are output by LOGV2_INFO(...) have the correct syslog severity level of Informational, but those with LogSeverity::Log() which are output by LOGV2(...) get the syslog severity level Debug. This inconsistency is likely what needs to be addressed here. I was able to replicate this in master.

Comment by Edwin Zhou [ 09/Jun/21 ]

Hi bhaarsma@cloudbilling.nl,

Thank you for clarifying that you were referring to outputting mongod log lines to syslog. It's a possible discrepancy mongod server logs with severity level of Informational are missing when viewing syslog with priority level of INFO. I'll pass this along to the appropriate team for further investigation.

Best,
Edwin

Comment by Bouke Haarsma [ 08/Jun/21 ]

Hi Edwin,

Re-reading my issue and the documentation I quoted, I might've conflated systemLog and auditLog. My issue is with output written to systemLog: the severity from the source (Mongo) doesn't seem to be mapped correctly with the target (syslog). Under the default settings of CentOS syslog will only log severity INFO or higher. For our use-case this is fine, as the log output from Mongo that we're interested in is also INFO (or higher). However with the default setup, we didn't see the messages we expected to see. After investigation we discovered that Mongo was writing INFO messages with a severity of DEBUG. This is unexpected behaviour.

Thanks,
Bouke

Comment by Edwin Zhou [ 07/Jun/21 ]

Hi bhaarsma@cloudbilling.nl,

I'm unable to find the slow query audit logs in the syslog and I'm unable reproduce this behavior. I am also unable to find under which action type a slow query audit log message should show up as.

To help further investigate, can you provide the following:

  1. The slow query log line found in your mongod logs
  2. The corresponding slow query audit log line with log level of DEBUG(7) as described in your description
  3. Your complete auditLog options

Best,
Edwin

Comment by Bouke Haarsma [ 19/May/21 ]

We're running CentOS Linux release 7.8.2003 (Core).

Generated at Thu Feb 08 05:40:52 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.