[SERVER-3795] All logfile lines should start with date Created: 09/Sep/11  Updated: 11/Jul/16  Resolved: 08/Nov/12

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: 1.8.3
Fix Version/s: 2.3.1

Type: Bug Priority: Major - P3
Reporter: Dominik Gehl Assignee: Shaun Verch
Resolution: Done Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by SERVER-7097 Missing endl in outOfSpace() Closed
Operating System: ALL
Participants:

 Description   

Most lines in the logfile start with the date the log entry was created, like
Fri Sep 9 03:41:07 [conn1618300] query [...] reslen:64 829ms
Unfortunately, sometime, there are also entries, which don't follow this convention, such as

2300/22660 10%
12000/22660 52%
19800/22660 87%
100/103 97%
3300/10050 32%
8700/23255 37%
19500/23255 83%
800/2111 37%
unindex failed (key too big?)

and some more.

The presence of these lines makes it way more difficult to parse the log file for important entries (with logwatch for example) ...



 Comments   
Comment by auto [ 06/Nov/12 ]

Author:

{u'date': u'2012-10-18T23:37:06Z', u'email': u'shaun.verch@10gen.com', u'name': u'Shaun Verch'}

Message: SERVER-3795 Rewrote multiline log statement to instead pass a string to msgasserted
Branch: master
https://github.com/mongodb/mongo/commit/7fe30630080c58565c3471efbfdd1e62694a79ef

Comment by auto [ 06/Nov/12 ]

Author:

{u'date': u'2012-09-27T23:42:56Z', u'email': u'shaun.verch@10gen.com', u'name': u'Shaun Verch'}

Message: SERVER-3795 Make sure every logical log statement ends with endl, so that the next log statement will begin with a date
Branch: master
https://github.com/mongodb/mongo/commit/48ee27067f024b23066070a7e1d5acd3e91960ee

Comment by Tad Marshall [ 23/Sep/12 ]

dominik The commit above fixes the case you reported, but we're going to do a more thorough audit to make sure that every intended complete log line ends with 'endl' so that the following line will start with a timestamp if it follows the normal logging conventions. Thanks for the report.

Comment by auto [ 23/Sep/12 ]

Author:

{u'date': u'2012-09-21T12:45:46-07:00', u'email': u'tad@10gen.com', u'name': u'Tad Marshall'}

Message: SERVER-3795 end logged lines with endl, not newline

Replace a newline in a message with an endl so we get the line break
logic in the logging code. Neaten up the code slightly and put quotes
around the 'id' so it looks like it belongs there.
Branch: master
https://github.com/mongodb/mongo/commit/aa36e3b343c3a3c23a773e587ab67184e66c9161

Comment by Tad Marshall [ 21/Sep/12 ]

Isn't there some kind of log class which writes to the file ? If yes, you could check all incoming log lines for the line ending and complete the line ending automatically there ... so no more hunting for correctly terminated log messages elsewhere ...

Yes and no. There are classes that do logging, but they are organized as "stream" interfaces, so the text sent to them comes in bits and we still need an explicit marker to say when the line is finished. There really are no "log lines" until the marker says that the line has ended. They look like "lines" in the output because we terminate them with line ending "stuff". We could treat newline the same as endl, but this sort of mixes two similar but distinct things and would be less flexible.

Given the way the code is written, the right "fix" is to use "endl" to end lines. We do that in something close to 100% of cases, so we just need to make it 100% and keep it there.

Comment by Shaun Verch [ 21/Sep/12 ]

I did a grep for \n"; and found a bunch of log messages that weren't terminated in endl. Should all log messages be terminated with endl? If you give me a few examples (for example, now I know "out()" should be), then I can just go put endl in all of those places.

Also, does anyone know why this actually happens?

Comment by Dominik Gehl [ 21/Sep/12 ]

Isn't there some kind of log class which writes to the file ? If yes, you could check all incoming log lines for the line ending and complete the line ending automatically there ... so no more hunting for correctly terminated log messages elsewhere ...

Comment by Tad Marshall [ 21/Sep/12 ]

Great; yes, this line was terminated with newline (backslash-n) and not endl. Easy to fix.

Comment by Dominik Gehl [ 21/Sep/12 ]

Here's the line missing the 'endl' (all the previouly shown lines seem to be preceded by this one):

Thu Sep 20 11:37:13 [conn1061] ClientCursor::find(): cursor not found in map -1 (ok after a drop)
getmore [...]

Comment by Tad Marshall [ 21/Sep/12 ]

You can get a log line that doesn't begin with a timestamp if the previous line failed to include an 'endl', so we need to see these in context to see what needs to be fixed. Please post a full log or at least a complete fragment so that we can look into any remaining issues.

Comment by Dominik Gehl [ 21/Sep/12 ]

Quick check of my log files showed that some of the lines in 2.2 still don't contain the date/time prefix:

end connection 127.0.0.1:42359 (48 connections now open)
update <db>.<coll> query:

{ ... } nscanned:1 nmoved:1 nupdated:1 keyUpdates:0 locks(micros) w:428087 428ms
getmore <db>.<coll> query: { ... }

cursorid:4072594741088413906 ntoreturn:0 keyUpdates:0 numYields: 13 locks(micros) r:15680 nreturned:698 reslen:217873 109ms
query <db>.<coll> query:

{ ... }

, $hint:

{ labels: 1 }

} cursorid:1261926605883642218 ntoreturn:0 ntoskip:0 nscanned:13260 keyUpdates:0 locks(micros) r:127982 nreturned:101 reslen:27282 127ms

Comment by Daniel Pasette (Inactive) [ 21/Sep/12 ]

This was fixed for the ProgressMeter in 2.2.0
What are the others you mentioned?

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