[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: |
|
||||||||
| Operating System: | ALL | ||||||||
| Participants: | |||||||||
| Description |
|
Most lines in the logfile start with the date the log entry was created, like 2300/22660 10% 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: |
| 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: |
| 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: Replace a newline in a message with an endl so we get the line break |
| Comment by Tad Marshall [ 21/Sep/12 ] |
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) |
| 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) getmore <db>.<coll> query: { ... } cursorid:4072594741088413906 ntoreturn:0 keyUpdates:0 numYields: 13 locks(micros) r:15680 nreturned:698 reslen:217873 109ms , $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 |