Opened 3 years ago

Last modified 2 years ago

#3813 new defect

"Unable to lock logger lockfile" message appears during unit test execution

Reported by: tmark Owned by:
Priority: low Milestone: Outstanding Tasks
Component: Unclassified Version: git
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: DHCP Feature Depending on Ticket:
Estimated Difficulty: 0 Add Hours to Ticket: 0
Total Hours: 0 Internal?: no

Description

During review of #3743, which added a new logger to DHCPv4 for logging bad packets Marcin noticed that the logging library kept emitting an error stating that it was unable to lock the log file:

"When I am running unit tests with verbose logging turned on I get the following error message before each logged message by bad-packet logger:

2015-04-17 12:11:58.145 ERROR [kea.bad-packet/14061] Unable to lock logger lockfile
2015-04-17 12:11:58.145 DEBUG [kea.bad-packet/14061] DHCP4_PACKET_DROP_0004 packet received on interface eth1 dropped, because of missing msg-type option

I am using OS-X for this test. Can you see the same thing?"

Analysis reveals that the error is an invalid fd passed into the fcntl() call made from within this method: InterprocessSyncFile::do_lock() in the logging library.

GoogleTests? are structured with a main() (see dhcp4/tests/main.cc) that calls their macro RUN_ALL_TESTS(). This executes all the tests that match the given test filter. Within this main() we initialize the logging system. All loggers created thereafter exist until we exit main(). The logging library does not expose a means to destroy them or to "un-initialize" the logging system.

The first time a logger is used once the process has started, it's LoggerImpl? is instantiated and it opens the logger lock file, retaining the fd returned by the open for all subsequent lock operations.

The code path through the tests in a given run determines which loggers are created and when. Note that each child logger will obtain a unique fd even though they all reference the same log file.

It appears that at some point after beginning of each individual test, GoogleTest? closes STDIN making 0 the next available fd. If the first use of a logger occurs AFTER this happens it will be assigned the 0 fd. Lock file locking will function correctly during the remainder of THAT test. However if the logger is used in subsequent tests, during the same test run, locking will fail because fd 0 is no longer valid because GoogleTest? has closed it.

I'm not quite sure what the correct fix for this should be. The log output
during the tests is still correct, tests still pass. It is only visibly noticeable if you enable log output by setting KEA_LOGGER_DESTINATION in the test environment.

To reproduce the issue:

% cd <kea>/src/bin/dhcp4
% export KEA_LOGGER_DESTINATION="stdout"
% export GTEST_FILTER="*.accept*"
% make check-TESTS

If you however you run Dhcpv4SrvTest.acceptMessageType by itself, the lock error for bad-packet logger does not occur.



Subtickets

Change History (2)

comment:1 Changed 3 years ago by hschempf

  • Milestone changed from Kea-proposed to DHCP Outstanding Tasks

comment:2 Changed 2 years ago by tomek

  • Milestone changed from DHCP Outstanding Tasks to Outstanding Tasks

Milestone renamed

Note: See TracTickets for help on using tickets.