MongoDB Experience: Server logging

By default the mongod process sends all output to stdout. You can also specify the daemon to log to file which is necessary for any production implementation. For example:

$ mongod --logpath=`pwd`/mongo.log  &
all output going to: /home/rbradfor/projects/mongo/mongo.log
^C

As you can see there is still a message to stdout, that should be cleaned up for a GA release. The output you will see for a clean startup/shutdown is:

Fri Jun 11 14:05:29 Mongo DB : starting : pid = 7990 port = 27017 dbpath = /home/rbradfor/projects/mongo/data/cu
rrent master = 0 slave = 0  64-bit
Fri Jun 11 14:05:29 db version v1.4.3, pdfile version 4.5
Fri Jun 11 14:05:29 git version: 47ffbdfd53f46edeb6ff54bbb734783db7abc8ca
Fri Jun 11 14:05:29 sys info: Linux domU-12-31-39-06-79-A1 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28
 EST 2009 x86_64 BOOST_LIB_VERSION=1_41
Fri Jun 11 14:05:29 waiting for connections on port 27017
Fri Jun 11 14:05:29 web admin interface listening on port 28017
Fri Jun 11 14:05:31 got kill or ctrl c signal 2 (Interrupt), will terminate after current cmd ends
Fri Jun 11 14:05:31 now exiting
Fri Jun 11 14:05:31  dbexit:
Fri Jun 11 14:05:31 	 shutdown: going to close listening sockets...
Fri Jun 11 14:05:31 	 going to close listening socket: 5
Fri Jun 11 14:05:31 	 going to close listening socket: 6
Fri Jun 11 14:05:31 	 shutdown: going to flush oplog...
Fri Jun 11 14:05:31 	 shutdown: going to close sockets...
Fri Jun 11 14:05:31 	 shutdown: waiting for fs preallocator...
Fri Jun 11 14:05:31 	 shutdown: closing all files...
Fri Jun 11 14:05:31      closeAllFiles() finished
Fri Jun 11 14:05:31 	 shutdown: removing fs lock...
Fri Jun 11 14:05:31  dbexit: really exiting now

MongoDB logging does not give an option to format the date/time appropriately. The format does not match the syslog of Ubuntu/CentOS

Jun  9 10:05:46 barney kernel: [1025968.983209] SGI XFS with ACLs, security attributes, realtime, large block/in
ode numbers, no debug enabled
Jun  9 10:05:46 barney kernel: [1025968.984518] SGI XFS Quota Management subsystem
Jun  9 10:05:46 barney kernel: [1025968.990183] JFS: nTxBlock = 8192, nTxLock = 65536
Jun  9 10:05:46 barney kernel: [1025969.007624] NTFS driver 2.1.29 [Flags: R/O MODULE].
Jun  9 10:05:46 barney kernel: [1025969.020995] QNX4 filesystem 0.2.3 registered.
Jun  9 10:05:46 barney kernel: [1025969.039264] Btrfs loaded
Jun  8 00:00:00 dc1 nagios: CURRENT HOST STATE: localhost;UP;HARD;1;PING OK - Packet loss = 0%, RTA = 0.01 ms
Jun  8 00:00:00 dc1 nagios: CURRENT SERVICE STATE: localhost;Current Load;OK;HARD;1;OK - load average: 0.00, 0.00, 0.00
Jun  8 00:00:00 dc1 nagios: CURRENT SERVICE STATE: localhost;Current Users;OK;HARD;1;USERS OK - 2 users currently logged in
Jun  8 00:00:00 dc1 nagios: CURRENT SERVICE STATE: localhost;HTTP;CRITICAL;HARD;4;Connection refused
Jun  8 00:00:00 dc1 nagios: CURRENT SERVICE STATE: localhost;PING;OK;HARD;1;PING OK - Packet loss = 0%, RTA = 0.01 ms
Jun  8 00:00:00 dc1 nagios: CURRENT SERVICE STATE: localhost;Root Partition;OK;HARD;1;DISK OK - free space: / 107259 MB (49% inode=98%):
Jun  8 00:00:00 dc1 nagios: CURRENT SERVICE STATE: localhost;SSH;OK;HARD;1;SSH OK - OpenSSH_4.3 (protocol 2.0)

And for reference here is the mysql format, which is also not configurable.

100605 16:43:38 mysqld_safe Starting mysqld daemon with databases from /opt/mysql51/data
100605 16:43:38 [Warning] '--log_slow_queries' is deprecated and will be removed in a future release. Please use ''--slow_query_log'/'--slow_query_log_fi
le'' instead.
100605 16:43:38 [Warning] '--log' is deprecated and will be removed in a future release. Please use ''--general_log'/'--general_log_file'' instead.
100605 16:43:38 [Warning] No argument was provided to --log-bin, and --log-bin-index was not used; so replication may break when this MySQL server acts a
s a master and has his hostname changed!! Please use '--log-bin=dc1-bin' to avoid this problem.
/opt/mysql51/bin/mysqld: File './dc1-bin.index' not found (Errcode: 13)
100605 16:43:38 [ERROR] Aborting

However unlike other products including MySQL the next execution of the mongod process overwrites the log file. This will catch some administrators out. You need to remember to also add –logappend. Personally I’d prefer to see this is the default

$ mongod --logpath=`pwd`/mongo.log --logappend

I did observe some confusion on messaging. Using the mongo shell you get a jumble of logging messages during a shutdown.

$ mongo
MongoDB shell version: 1.4.3
url: test
connecting to: test
type "help" for help
> use admin
switched to db admin
> db.shutdownServer();
Fri Jun 11 13:54:08 query failed : admin.$cmd { shutdown: 1.0 } to: 127.0.0.1
server should be down...
Fri Jun 11 13:54:08 trying reconnect to 127.0.0.1
Fri Jun 11 13:54:08 reconnect 127.0.0.1 ok
Fri Jun 11 13:54:08 query failed : admin.$cmd { getlasterror: 1.0 } to: 127.0.0.1
Fri Jun 11 13:54:08 JS Error: Error: error doing query: failed (anon):1284
> exit
bye

This also results in an unformatted message in the log file for some reason.

$ tail mongo.log
Fri Jun 11 13:54:08 	 shutdown: removing fs lock...
Fri Jun 11 13:54:08  dbexit: really exiting now
Fri Jun 11 13:54:08 got request after shutdown()
ERROR: Client::~Client _context should be NULL: conn

Nothing of any critical nature however all important for system administrators that have monitoring scripts or using monitoring products.

Trackbacks

  1. MongoDB Experience: Server logging…

    By default the mongod process sends all output to stdout. You can also specify the daemon to log to file which is necessary for any production implementation. For example: $ mongod –logpath=`pwd`/mongo.log & all output going to: /home/rbradfor/project…