Opened 6 years ago

Last modified 4 years ago

#2988 assigned defect

check and report log4cplus rotation issues

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

Description

see http://bind10.isc.org/ticket/1622#comment:34

There's still an issue of log4cplus in log file rotation (some log
messages can go to an already rolled file). Check if latest versions
of log4cplus (1.1.1 and 1.1.2rcX) still have this issue (from a quick
look at changelogs they still seem to have the problem), and if they
do, report it to the log4cplus developer.

Subtickets

Change History (13)

comment:1 Changed 6 years ago by muks

  • Estimated Difficulty changed from 0 to 2

comment:2 follow-up: Changed 6 years ago by jreed

I patched log4cplus a few days ago so it would check and do rotation before logging. It appears to work for me. I sent an email with the minor patch to the log4cplus developers list on June 10. Now waiting for response.

comment:3 Changed 6 years ago by jreed

The patch I used is:

--- ./src/fileappender.cxx.orig	2013-06-07 11:43:19.000000000 -0500
+++ ./src/fileappender.cxx	2013-06-07 11:45:06.000000000 -0500
@@ -488,11 +488,13 @@
 void
 RollingFileAppender::append(const spi::InternalLoggingEvent& event)
 {
-    FileAppender::append(event);
 
+    // Rotate log file if needed before appending to it.
     if(out.tellp() > maxFileSize) {
         rollover(true);
     }
+
+    FileAppender::append(event);
 }
 

But this introduced test failures like:

[ RUN      ] LoggerManagerTest.FileSizeRollover
logger_manager_unittest.cc:151: Failure
Failed
Unable to open the logging file ./bind10_logger_manager_test_8Cmo6l.2
logger_manager_unittest.cc:165: Failure
Value of: line.find(string(*i)) != string::npos
  Actual: false
Expected: true
Expected to find LOG_DUPLICATE_NAMESPACE on line 1 of logging file ./bind10_logger_manager_test_8Cmo6l.1
logger_manager_unittest.cc:165: Failure
Value of: line.find(string(*i)) != string::npos
  Actual: false
Expected: true
Expected to find LOG_DUPLICATE_NAMESPACE on line 1 of logging file ./bind10_logger_manager_test_8Cmo6l.2
logger_manager_unittest.cc:165: Failure
Value of: line.find(string(*i)) != string::npos
  Actual: false
Expected: true
Expected to find LOG_NO_MESSAGE_TEXT on line 1 of logging file ./bind10_logger_manager_test_8Cmo6l.1
[  FAILED  ] LoggerManagerTest.FileSizeRollover (10 ms)

These tests may need to be rewritten to handle rotation before logging.

Last edited 6 years ago by jreed (previous) (diff)

comment:4 Changed 6 years ago by muks

  • Milestone changed from New Tasks to Sprint-20130709

comment:5 in reply to: ↑ 2 ; follow-up: Changed 6 years ago by jinmei

Replying to jreed:

I patched log4cplus a few days ago so it would check and do rotation before logging. It appears to work for me. I sent an email with the minor patch to the log4cplus developers list on June 10. Now waiting for response.

Did you get any response?

comment:6 follow-up: Changed 6 years ago by jreed

It mostly works but sometimes I have logs out of order, for example:

-rw-r--r--  1 root  reed  1049289 Jun 22 23:15 bind10.log.15
-rw-r--r--  1 root  reed  1049512 Jun 23 09:48 bind10.log.14
-rw-r--r--  1 root  reed  1049053 Jun 23 21:48 bind10.log.12
-rw-r--r--  1 root  reed  1049104 Jun 23 22:00 bind10.log.11
-rw-r--r--  1 root  reed  1049588 Jun 24 00:00 bind10.log.13
-rw-r--r--  1 root  reed  1049514 Jun 24 09:49 bind10.log.10
-rw-r--r--  1 root  reed  1049271 Jun 24 12:00 bind10.log.9

See the last log entries; bind10.log.13 is in odd order:

==> bind10.log.9 <==
2013-06-24 12:00:01.574 DEBUG [b10-resolver.resolver/19136] RESOLVER_DNS_MESSAGE_RECEIVED DNS message received: ;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 27580
...

==> bind10.log.10 <==
2013-06-24 09:48:34.867 DEBUG [b10-zonemgr.zonemgr/28897] ZONEMGR_REFRESH_ZONE refreshing zone foo. (class IN)

==> bind10.log.11 <==
2013-06-23 22:00:19.940 DEBUG [b10-auth.cc/22909] CC_GROUP_RECEIVE trying to receive a message with seq -1

==> bind10.log.12 <==
2013-06-23 21:48:31.904 DEBUG [b10-zonemgr.zonemgr/28897] ZONEMGR_REFRESH_ZONE refreshing zone foo. (class IN)

==> bind10.log.13 <==
2013-06-24 00:00:00.625 DEBUG [b10-resolver.resolver/19136] RESOLVER_DNS_MESSAGE_RECEIVED DNS message received: ;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 7479
...

==> bind10.log.14 <==
2013-06-23 09:48:30.876 DEBUG [b10-zonemgr.zonemgr/28897] ZONEMGR_REFRESH_ZONE refreshing zone foo. (class IN)

==> bind10.log.15 <==
2013-06-22 23:15:18.404 DEBUG [b10-resolver.resolver/19136] RESOLVER_DNS_MESSAGE_RECEIVED DNS message received: ;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 38951
...

comment:7 in reply to: ↑ 5 Changed 6 years ago by jreed

Replying to jinmei:

Replying to jreed:

I patched log4cplus a few days ago so it would check and do rotation before logging. It appears to work for me. I sent an email with the minor patch to the log4cplus developers list on June 10. Now waiting for response.

Did you get any response?

No response yet.

comment:8 in reply to: ↑ 6 Changed 6 years ago by jinmei

Replying to jreed:

It mostly works but sometimes I have logs out of order, for example:

-rw-r--r--  1 root  reed  1049289 Jun 22 23:15 bind10.log.15
-rw-r--r--  1 root  reed  1049512 Jun 23 09:48 bind10.log.14
-rw-r--r--  1 root  reed  1049053 Jun 23 21:48 bind10.log.12
-rw-r--r--  1 root  reed  1049104 Jun 23 22:00 bind10.log.11
-rw-r--r--  1 root  reed  1049588 Jun 24 00:00 bind10.log.13
-rw-r--r--  1 root  reed  1049514 Jun 24 09:49 bind10.log.10
-rw-r--r--  1 root  reed  1049271 Jun 24 12:00 bind10.log.9

See the last log entries; bind10.log.13 is in odd order:

Could it be possible that the offending process uses the
wrong/unpatched version of liblog4cplus?

comment:9 Changed 6 years ago by jreed

Just one version of log4cplus installed. It is 1.1.1.

Here is an example of out of order:

-rw-r--r--  1 root  reed  1049295 Jul 27 09:22 bind10.log.17
-rw-r--r--  1 root  reed  1049028 Jul 27 20:29 bind10.log.15
-rw-r--r--  1 root  reed  1049635 Jul 27 23:15 bind10.log.16
-rw-r--r--  1 root  reed  1049194 Jul 28 08:28 bind10.log.13
-rw-r--r--  1 root  reed  1049376 Jul 28 09:22 bind10.log.14
-rw-r--r--  1 root  reed  1049041 Jul 28 20:30 bind10.log.11
-rw-r--r--  1 root  reed  1049508 Jul 29 00:00 bind10.log.12
-rw-r--r--  1 root  reed  1049335 Jul 29 08:19 bind10.log.10
-rw-r--r--  1 root  reed  1049977 Jul 29 10:24 bind10.log.9

comment:10 Changed 6 years ago by muks

  • Owner set to jreed
  • Status changed from new to assigned

Jeremy, please can you contact the log4cplus developer about this issue again?

comment:11 Changed 6 years ago by stephen

  • Milestone changed from bind10-1.2-release-freeze to Common Outstanding Tasks

comment:12 Changed 4 years ago by tomek

  • Milestone changed from Common Outstanding Tasks to DHCP Outstanding Tasks

comment:13 Changed 4 years ago by tomek

  • Milestone changed from DHCP Outstanding Tasks to Outstanding Tasks

Milestone renamed

Note: See TracTickets for help on using tickets.