Opened 9 years ago

Closed 9 years ago

#1024 closed task (complete)

increase logging verbosity in unittests

Reported by: jinmei Owned by: stephen
Priority: medium Milestone: Sprint-20110802
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.0 Add Hours to Ticket: 0
Total Hours: 0 Internal?: no

Description

See #1023.

The actual "fix" should be quite trivial.

Subtickets

Change History (17)

comment:1 Changed 9 years ago by jinmei

Note: we probably want to have a run time switch to specify the
verbosity. See http://bind10.isc.org/ticket/999#comment:18

comment:2 Changed 9 years ago by stephen

  • Milestone changed from Next-Sprint-Proposed to Sprint-20110712

comment:3 Changed 9 years ago by jinmei

Since this feature seemed to be a bit controversial, I'll describe
some more rationale for that.

There can be (and actually was as we saw in #1023) a bug in producing
a debug logging message (or in general log messages at a lower
severity that wouldn't be generated by default). Unless we enable
that level of logging we'll keep missing that type of regression.

There was a suggestion that it would be better to have explicit tests
on logging outputs. I don't deny that, but it doesn't seem to be
possible quickly and would be a kind of middle to long term
enhancements. On the other hand, it's more short term, IMO, to be
able to detect regression in log outputs through our regular tests.
If, in future, separate tests eliminate the need for relying on the
side effect by increasing the log level, we can revert it. But as a
short term improvement I believe we should do it now.

Another note: it would be better to do this ticket after #1071 if
it gets completed quickly. Then we can avoid having a period of
making log output noisier. But if #1071 is not completed, say, within
one week, I suggest we start and complete this task regardless of the
progress of #1071.

comment:4 Changed 9 years ago by stephen

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

comment:5 Changed 9 years ago by stephen

  • Component changed from Unclassified to logging
  • Estimated Difficulty changed from 0.0 to 0.5
  • Owner changed from stephen to UnAssigned
  • Status changed from assigned to reviewing

This needs to be merged after #1084.

comment:6 Changed 9 years ago by vorner

  • Owner changed from UnAssigned to stephen

The code itself looks OK and after reading jinmei's rationale, I understand the reason for the verbosity. It runs when merged with master (with the bugfix).

Anyway, do we expect some integration with the NULL output? Because, as I wrote in the linked ticket, this produces huge amount of red lines for me which is stressful and bad for the eyes (OK, exaggerating little bit, but it has bad aesthetic effect on the bunch of green OKs).

This is OK to merge.

comment:7 Changed 9 years ago by stephen

Anyway, do we expect some integration with the NULL output?

I won't commit this ticket until after #1071, after which you can route message output to /dev/null. I've written some text on this (see section on "Logging Initialization" in LoggingCppApiDesign) but will highlight it in an email to bind10-dev.

comment:8 Changed 9 years ago by jreed

Way too much noise by default. Well over 24,000 log lines (even with incomplete run). Please by default just log to /dev/null.

comment:9 Changed 9 years ago by jreed

I am not sure if this was introduced in this trac1024 branch, but I don't recall seeing it previously:

[----------] 30 tests from MemoryZoneTest
[ RUN      ] MemoryZoneTest.constructor
2011-07-07 08:05:42.462 DEBUG [bind10.datasrc] DATASRC_MEM_CREATE creating zone 'example.org.' in 'IN' class
2011-07-07 08:05:42.463 DEBUG [bind10.datasrc] DATASRC_MEM_DESTROY destroying zone 'example.org.' in 'IN' class
[       OK ] MemoryZoneTest.constructor (2 ms)
[ RUN      ] MemoryZoneTest.add
2011-07-07 08:05:42.463 DEBUG [bind10.datasrc] DATASRC_MEM_CREATE creating zone 'example.org.' in 'IN' class
2011-07-07 08:05:42.463 DEBUG [bind10.datasrc] DATASRC_MEM_ADD_RRSET adding RRset 'example.com./A' into zone 'example.org.'
2011-07-07 08:05:42.464 ERROR [bind10.datasrc] DATASRC_MEM_OUT_OF_ZONE domain 'example.com.' doesn't belong to zone 'example.org.'
assertion "px != 0" failed: file "/usr/pkg/include/boost/smart_ptr/shared_ptr.hpp", line 418, function "T* boost::shared_ptr< <template-parameter-1-1> >::operator->() const [with T = const isc::dns::RRset]"
[1]   Abort trap (core dumped) ${dir}${tst}
FAIL: run_unittests

gdb:

(gdb) bt
#0  0x00007f7ff8ee54aa in _lwp_kill () from /usr/lib/libc.so.12
#1  0x00007f7ff8ee4e1e in abort () from /usr/lib/libc.so.12
#2  0x00007f7ff8e5f2d4 in __assert13 () from /usr/lib/libc.so.12
#3  0x00007f7ffd0441c0 in isc::datasrc::MemoryZone::MemoryZoneImpl::add (
    this=0x7f7ffd710b60, rrset=@0x7f7fffffd4b0, domains=0x7f7ffd710ba0)
    at /usr/pkg/include/boost/smart_ptr/shared_ptr.hpp:418
#4  0x00000000004a9ddd in (anonymous namespace)::MemoryZoneTest_add_Test::TestBody (this=0x7f7ffd782160) at memory_datasrc_unittest.cc:359
#5  0x00007f7ffda25102 in testing::Test::Run () from /usr/pkg/lib/libgtest.so.0
#6  0x00007f7ffda2520f in testing::internal::TestInfoImpl::Run ()
   from /usr/pkg/lib/libgtest.so.0
#7  0x00007f7ffda252d4 in testing::TestCase::Run ()
   from /usr/pkg/lib/libgtest.so.0
#8  0x00007f7ffda2663b in testing::internal::UnitTestImpl::RunAllTests ()
   from /usr/pkg/lib/libgtest.so.0
#9  0x00000000004276ef in main (argc=1, argv=<value optimized out>)
    at run_unittests.cc:28

comment:10 Changed 9 years ago by stephen

  • Owner changed from stephen to jreed

Way too much noise by default. Well over 24,000 log lines (even with incomplete run). Please by default just log to /dev/null.

Done. To make the output visible, set the environment variable B10_LOGGER_DESTINATION to stdout or stderr. (I'll send an email round to bind10-dev to flag this and update the page in the wiki before I merge.)

I am not sure if this was introduced in this trac1024 branch, but I don't recall seeing it previously ...

This problem was fixed in #1084. Prior to making this change (to log to /dev/null by default), I merged master into the branch. When you run the test, this should be fixed.

comment:11 Changed 9 years ago by jreed

The OutputOptionTest? still logs:

2011-07-07 16:10:47.981 WARN  [bind10.log] LOG_DUPLICATE_MESSAGE_ID duplicate message ID (LOG_DUPLICATE_NAMESPACE) in compiled code

And:

[ RUN      ] LoggerSupportTest.LoggingInitializationCheck
2011-07-07 16:10:47.987 INFO  [bind10.test] LOG_INPUT_OPEN_FAIL unable to open message file %1 for input: %2
[       OK ] LoggerSupportTest.LoggingInitializationCheck (0 ms)

And

[ RUN      ] LoggerLevel.getSeverity
2011-07-07 16:10:48.011 ERROR [bind10.log] LOG_BAD_SEVERITY unrecognized log severity: some bad value
2011-07-07 16:10:48.011 ERROR [bind10.log] LOG_BAD_SEVERITY unrecognized log severity: 
[       OK ] LoggerLevel.getSeverity (1 ms)

And

[ RUN      ] LoggerLevelImplTest.FromString
2011-07-07 16:10:48.012 WARN  [bind10.log] LOGIMPL_BELOW_MIN_DEBUG debug level of -5 is too low and will be set to the minimum of 0
2011-07-07 16:10:48.012 WARN  [bind10.log] LOGIMPL_BELOW_MIN_DEBUG debug level of -4 is too low and will be set to the minimum of 0
2011-07-07 16:10:48.012 WARN  [bind10.log] LOGIMPL_BELOW_MIN_DEBUG debug level of -3 is too low and will be set to the minimum of 0
2011-07-07 16:10:48.012 WARN  [bind10.log] LOGIMPL_BELOW_MIN_DEBUG debug level of -2 is too low and will be set to the minimum of 0
2011-07-07 16:10:48.012 WARN  [bind10.log] LOGIMPL_BELOW_MIN_DEBUG debug level of -1 is too low and will be set to the minimum of 0
2011-07-07 16:10:48.012 WARN  [bind10.log] LOGIMPL_ABOVE_MAX_DEBUG debug level of 100 is too high and will be set to the maximum of 99
2011-07-07 16:10:48.012 WARN  [bind10.log] LOGIMPL_ABOVE_MAX_DEBUG debug level of 101 is too high and will be set to the maximum of 99
2011-07-07 16:10:48.012 WARN  [bind10.log] LOGIMPL_ABOVE_MAX_DEBUG debug level of 102 is too high and will be set to the maximum of 99
2011-07-07 16:10:48.012 WARN  [bind10.log] LOGIMPL_ABOVE_MAX_DEBUG debug level of 103 is too high and will be set to the maximum of 99
[       OK ] LoggerLevelImplTest.FromString (1 ms)

And

Running test: log_test.py
.......2011-07-07 16:11:19.329 INFO  [root.log] LOG_READING_LOCAL_FILE reading local message file /no/such/file
2011-07-07 16:11:19.329 ERROR [root.log] LOG_INPUT_OPEN_FAIL unable to open message file /no/such/file for input: No such file or directory
..

And

[ RUN      ] IOFetchTest.TcpTimeout
2011-07-07 16:11:28.443 ERROR [unittest.asiolink] ASIODNS_OPEN_SOCKET error 61 opening TCP socket to 127.0.0.1(5301)
[       OK ] IOFetchTest.TcpTimeout (4011 ms)

And

Running test: bind10_test.py
.......2011-07-07 16:12:28.408 WARN  [b10-boss.boss] BIND10_PROCESS_ENDED_WITH_EXIT_STATUS process b10-auth (PID 5) terminated, exit status = 0

And

Running test: cmdctl_test.py
2011-07-07 16:12:42.543 ERROR [b10-cmdctl.cmdctl] CMDCTL_BAD_CONFIG_DATA error in config data: unknown config item: non-exist
2011-07-07 16:12:42.545 ERROR [b10-cmdctl.cmdctl] CMDCTL_BAD_CONFIG_DATA error in config data: the file doesn't exist: /user/non-exist_folder
2011-07-07 16:12:42.546 ERROR [b10-cmdctl.cmdctl] CMDCTL_BAD_CONFIG_DATA error in config data: the file doesn't exist: /user/non-exist_folder
2011-07-07 16:12:42.547 ERROR [b10-cmdctl.cmdctl] CMDCTL_BAD_CONFIG_DATA error in config data: Invalid accounts file: [Errno 2] No such file or directory: '/user/non-exist_folder'
2011-07-07 16:12:42.673 ERROR [b10-cmdctl.cmdctl] CMDCTL_BAD_CONFIG_DATA error in config data: Invalid accounts file: list index out of range
.......2011-07-07 16:12:42.701 INFO  [b10-cmdctl.cmdctl] CMDCTL_BAD_PASSWORD bad password for user: root
....2011-07-07 16:12:42.707 INFO  [b10-cmdctl.cmdctl] CMDCTL_NO_SUCH_USER username not found in user database: root
................2011-07-07 16:12:42.946 ERROR [b10-cmdctl.cmdctl] CMDCTL_USER_DATABASE_READ_ERROR failed to read user database file /local/not-exist: [Errno 2] 
No such file or directory: '/local/not-exist'
2011-07-07 16:12:42.946 ERROR [b10-cmdctl.cmdctl] CMDCTL_NO_USER_ENTRIES_READ failed to read user information, all users will be denied
.2011-07-07 16:12:42.957 INFO  [b10-cmdctl.cmdctl] CMDCTL_SSL_SETUP_FAILURE_USER_DENIED failed to create an SSL connection (user denied): key file '../cmdctl-keyfile' doesn't exist 
}}

And

{{{

Running test: xfrout_test.py
......2011-07-07 16:12:46.914 ERROR [b10-xfrout.xfrout] XFROUT_REMOVE_OLD_UNIX_SOCKET_FILE_ERROR error removing unix socket file /tmp/tmpZ738Hb: [Errno 1] Operation not permitted: '/tmp/tmpZ738Hb'
.2011-07-07 16:12:46.918 ERROR [b10-xfrout.xfrout] XFROUT_UNIX_SOCKET_FILE_IN_USE another xfrout process seems to be using the unix socket file temp.sock.file
....2011-07-07 16:12:46.923 INFO  [b10-xfrout.xfrout] XFROUT_NEW_CONFIG Update xfrout configuration
2011-07-07 16:12:46.923 INFO  [b10-xfrout.xfrout] XFROUT_NEW_CONFIG_DONE Update xfrout configuration done
2011-07-07 16:12:46.924 INFO  [b10-xfrout.xfrout] XFROUT_NEW_CONFIG Update xfrout configuration
2011-07-07 16:12:46.924 INFO  [b10-xfrout.xfrout] XFROUT_NEW_CONFIG_DONE Update xfrout configuration done
2011-07-07 16:12:46.924 INFO  [b10-xfrout.xfrout] XFROUT_NEW_CONFIG Update xfrout configuration
2011-07-07 16:12:46.929 ERROR [b10-xfrout.xfrout] XFROUT_BAD_TSIG_KEY_STRING bad TSIG key string: bad..example.com:SFuWd/q99SzF8Yzd1QbB9g==
2011-07-07 16:12:46.929 INFO  [b10-xfrout.xfrout] XFROUT_NEW_CONFIG_DONE Update xfrout configuration done
....2011-07-07 16:12:46.931 ERROR [b10-xfrout.xfrout] XFROUT_PARSE_QUERY_ERROR error parsing query: Malformed DNS message (short length): 7
.2011-07-07 16:12:46.931 INFO  [b10-xfrout.xfrout] XFROUT_AXFR_TRANSFER_STARTED transfer of zone example.com/IN has started
2011-07-07 16:12:46.931 INFO  [b10-xfrout.xfrout] XFROUT_AXFR_TRANSFER_DONE transfer of example.com/IN complete
.2011-07-07 16:12:46.932 INFO  [b10-xfrout.xfrout] XFROUT_AXFR_TRANSFER_FAILED transfer of example.com/IN failed, rcode: NOTAUTH
}}}

I guess I should not have copied all these here... I realize now these are all not DEBUG?  Maybe they should be excluded too?

I core dump problem is gone. Thanks.

comment:12 Changed 9 years ago by jreed

  • Owner changed from jreed to stephen

comment:13 Changed 9 years ago by stephen

  • Owner changed from stephen to vorner

LoggerXxxx tests

There is one message that is unavoidable, as it is generated in a test of the logging initialization code (so can't be overridden without affecting the initialization under test).

log_test.py

Two messages are generated here that are not easy to suppress. This code tests the Python logging so overriding the logging destination could affect the validity of the test.

IOFetchTest.TcpTimeout

Fixed.

bind10_test.py
cmdctl_test.py
xfrout_test.py

Done. Added a resetUnitTestRootLogger() function to be called in the unit tests's __init__ method that sets the logging parameters to the same as those used in the C++ unit tests.

comment:14 Changed 9 years ago by vorner

  • Owner changed from vorner to stephen

It seems OK to merge.

comment:15 Changed 9 years ago by stephen

  • Owner changed from stephen to vorner

It occurs to me that this should have a ChangeLog entry. Suggest:

XXX.	[func]		stephen
	Default logging for unit tests is severity DEBUG (level 99), with
        output routed to /dev/null.  This can be altered by setting the
        B10_LOGGER_XXX environment variables.
	(Trac #1024, git yyyyy)

comment:16 Changed 9 years ago by vorner

  • Owner changed from vorner to stephen

Well, this might be questionable if this is a user-visible feature, but maybe yes. This one looks OK.

comment:17 Changed 9 years ago by stephen

  • Estimated Difficulty changed from 0.5 to 2
  • Resolution set to complete
  • Status changed from reviewing to closed

Merged in commit 72a0beb8dfe85b303f546d09986461886fe7a3d8

Note: See TracTickets for help on using tickets.