Opened 9 years ago

Closed 6 years ago

#1033 closed defect (fixed)

need unittest for %q and log time

Reported by: jreed Owned by: muks
Priority: medium Milestone: Sprint-20131015
Component: logging Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: Core Feature Depending on Ticket:
Estimated Difficulty: 0.0 Add Hours to Ticket: 0
Total Hours: 0 Internal?: no

Description

%q is not portable, not a standard.

See output:

2011-06-21 15:12:56.q DEBUG [b10-auth.datasrc] DATASRC_SQLITE_CREATE, SQLite data source created

"q" is not replaced.

Subtickets

Change History (17)

comment:1 Changed 9 years ago by jreed

src/lib/log/logger_manager_impl.cc

comment:2 Changed 9 years ago by stephen

This may indicate a bug in log4cplus. In the log4cplus documentation, the %q format is marked as:

%q -- milliseconds as decimal(0-999) -- Log4CPLUS specific

... and as far as I can see in the log4cplus code, it is explicitly checked for and replaced with the milliseconds value (in the method Time::getFormattedTime() in timehelper.cxx).

What operating system was this on?

comment:3 Changed 9 years ago by stephen

Actually, what may be more relevant is what version of log4cplus is installed? The version I looked at was the latest, 1.0.4

comment:4 Changed 9 years ago by jreed

FreeBSD 8.2-RELEASE (amd64) virtual machine.

Using package provided by FreeBSD: log4cplus-1.0.2_1

It works on my NetBSD system, for example: 11:06:55.732

I will get an updated package for FreeBSD (or make one myself).

If that doesn't work, I will look at the build on FreeBSD to see how the configure detected the time functionalities. (I see trunk of log4cplus has many changes here too.)

comment:5 Changed 9 years ago by stephen

I think using 1.0.2 of log4cplus is the problem. That version uses strftime() to replace the tokens, then replaces any "%q"s remaining with the milliseconds value. 1.0.4 first replaces "%q", then calls strftime().

If the FreeBSD version of strftime() is removing the percent sign in "%q" (and leaving the "q") when it processes it because it doesn't recognise the token, we would get the behaviour we're seeing.

comment:6 Changed 9 years ago by jreed

  • Resolution set to complete
  • Status changed from new to closed

Okay I verified that newer log4cplus works.

I documented the requirement in the bind10 guide.

Closing ticket.

comment:7 Changed 9 years ago by jreed

  • Resolution complete deleted
  • Status changed from closed to reopened

Re-opening ticket. This should have a unittest that will prove that the format of the log message, in particular the time stamp, is correct.

comment:8 Changed 9 years ago by shane

  • Milestone changed from New Tasks to Year 3 Task Backlog

comment:9 Changed 9 years ago by jreed

  • Summary changed from %q and log time to need unittest for %q and log time

comment:10 Changed 6 years ago by muks

  • Milestone set to Sprint-20131015
  • Owner set to UnAssigned
  • Status changed from reopened to reviewing

Up for review.

comment:11 Changed 6 years ago by muks

No ChangeLog? entry is required.

comment:12 Changed 6 years ago by kean

  • Owner changed from UnAssigned to kean

comment:13 Changed 6 years ago by kean

  • Owner changed from kean to muks

Tested with log4cplus 1.1.1, the one that comes with FC19. Looks good. My only comment on the test is that it relies on deep knowledge of what the default format is. It would be better to explicitly set the layout pattern that you are using the regex against (which would mean you could make the regex a lot simpler too, it just needs to include %D{%q}), so that the test is insulated from changes in the future (as unlikely as that is).

comment:14 Changed 6 years ago by muks

  • Owner changed from muks to kean

I don't follow the last comment. Please can you explain with an example what you are suggesting?

comment:15 Changed 6 years ago by kean

  • Owner changed from kean to muks

The default pattern for log messages is set in logger_manager_impl.cc to be "%D{%Y-%m-%d %H:%M:%S.%q} %-5p [%c/%i] %m\n". That is the pattern your regex is testing against. If that pattern can be changed by the caller to be simply "%D{%q}" you can greatly reduce the complexity of the regex, and check for just that feature, since that is what the bug is about. If you can't easily change the pattern, then its fine to merge as is.

comment:16 Changed 6 years ago by muks

Ah.. the layout pattern is fixed (we don't want to change it) and the test is actually to check for that particular pattern rather than if any given pattern is being renderered correctly. I remember seeing another ticket about this problem too.

I'll merge and close this ticket soon.

comment:17 Changed 6 years ago by muks

  • Resolution set to fixed
  • Status changed from reviewing to closed

Merged to master branch in commit 3acb0511190ab3c0b2711f712adfef35c172af05:

* f45a1ff [1033] Add unittest for log layout pattern

Resolving as fixed. Thank you for the review Kean.

Note: See TracTickets for help on using tickets.