Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

DM-7509: Fix two bugs in handling strings with %s #14

Merged
merged 4 commits into from
Sep 3, 2016
Merged

DM-7509: Fix two bugs in handling strings with %s #14

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
ac7c41c
Fix two bugs in handling strings with %s
r-owen Sep 2, 2016
4546613
Standardize import order in test
r-owen Sep 3, 2016
b418190
Standardize test names to start with "test"
r-owen Sep 3, 2016
e6c6b0a
Hide too-long line from flake8 in test
r-owen Sep 3, 2016
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
3 changes: 1 addition & 2 deletions .gitignore
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,8 +16,7 @@ config.log
/lib/liblog.*
/tests/.cache
/tests/.tests
/tests/cppTest
/tests/logTest
/tests/testLog
version.py
.coverage
*.gcda
Expand Down
4 changes: 2 additions & 2 deletions python/lsst/log/log.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -172,8 +172,8 @@ def handle(self, record):
logging.Handler.handle(self, record)

def emit(self, record):
Log.getLogger(record.name).log(self.translateLevel(record.levelno), record.filename,
record.funcName, record.lineno, record.msg % record.args)
Log.getLogger(record.name).logMsg(self.translateLevel(record.levelno), record.filename,
record.funcName, record.lineno, record.msg % record.args)

def translateLevel(self, levelno):
"""
Expand Down
16 changes: 8 additions & 8 deletions python/lsst/log/logLib.i
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -61,12 +61,10 @@ import os
%include "lsst/log/Log.h"

%extend lsst::log::Log {
void log(int level, std::string const& filename,
std::string const& funcname, unsigned int lineno,
std::string const& msg) {
self->log(log4cxx::Level::toLevel(level),
log4cxx::spi::LocationInfo(filename.c_str(), funcname.c_str(), lineno),
msg.c_str());
void logMsg(int level, std::string const& filename,
std::string const& funcname, unsigned int lineno, std::string const& msg) {
self->logMsg(log4cxx::Level::toLevel(level),
log4cxx::spi::LocationInfo(filename.c_str(), funcname.c_str(), lineno), msg.c_str());
};
unsigned lwpID() { return lsst::log::lwpID(); };

Expand Down Expand Up @@ -100,8 +98,10 @@ import os
if self.isEnabledFor(level):
frame = inspect.currentframe().f_back # calling method
frame = frame.f_back # original log location
self.log(level, os.path.split(frame.f_code.co_filename)[1],
inspect.stack()[2][3], frame.f_lineno, fmt % args)
filename=os.path.split(frame.f_code.co_filename)[1]
funcname=inspect.stack()[2][3]
msg=fmt % args if args else fmt
self.logMsg(level, filename, funcname, frame.f_lineno, msg)
}
}

26 changes: 13 additions & 13 deletions tests/logTest.cc → tests/testLog.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -87,7 +87,7 @@ struct LogFixture {
{
// PATH_MAX should be more than enough to hold the temp dir and file name
char cname[PATH_MAX];
strncpy(cname, P_tmpdir "/logTest-XXXXXXXXX", sizeof(cname));
strncpy(cname, P_tmpdir "/testLog-XXXXXXXXX", sizeof(cname));
cname[sizeof(cname)-1] = '\0'; // Just in case
fd = mkstemp(cname);
if (fd == -1) {
Expand Down Expand Up @@ -247,16 +247,16 @@ BOOST_FIXTURE_TEST_CASE(context_stream, LogFixture) {
BOOST_FIXTURE_TEST_CASE(pattern_stream, LogFixture) {

std::string expected_msg =
"INFO root pattern_stream test_method (tests/logTest.cc:%1%) tests/logTest.cc(%1%) - This is INFO - {}\n"
"DEBUG root pattern_stream test_method (tests/logTest.cc:%2%) tests/logTest.cc(%2%) - This is DEBUG - {}\n"
"INFO root pattern_stream test_method (tests/logTest.cc:%3%) tests/logTest.cc(%3%) - This is INFO 2 - {{x,3}{y,foo}}\n"
"DEBUG root pattern_stream test_method (tests/logTest.cc:%4%) tests/logTest.cc(%4%) - This is DEBUG 2 - {{x,3}{y,foo}}\n"
"INFO component pattern_stream test_method (tests/logTest.cc:%5%) tests/logTest.cc(%5%) - This is INFO 3 - {{x,3}{y,foo}}\n"
"DEBUG component pattern_stream test_method (tests/logTest.cc:%6%) tests/logTest.cc(%6%) - This is DEBUG 3 - {{x,3}{y,foo}}\n"
"INFO component pattern_stream test_method (tests/logTest.cc:%7%) tests/logTest.cc(%7%) - This is INFO 4 - {{y,foo}}\n"
"DEBUG component pattern_stream test_method (tests/logTest.cc:%8%) tests/logTest.cc(%8%) - This is DEBUG 4 - {{y,foo}}\n"
"INFO root pattern_stream test_method (tests/logTest.cc:%9%) tests/logTest.cc(%9%) - This is INFO 5 - {{y,foo}}\n"
"DEBUG root pattern_stream test_method (tests/logTest.cc:%10%) tests/logTest.cc(%10%) - This is DEBUG 5 - {{y,foo}}\n";
"INFO root pattern_stream test_method (tests/testLog.cc:%1%) tests/testLog.cc(%1%) - This is INFO - {}\n"
"DEBUG root pattern_stream test_method (tests/testLog.cc:%2%) tests/testLog.cc(%2%) - This is DEBUG - {}\n"
"INFO root pattern_stream test_method (tests/testLog.cc:%3%) tests/testLog.cc(%3%) - This is INFO 2 - {{x,3}{y,foo}}\n"
"DEBUG root pattern_stream test_method (tests/testLog.cc:%4%) tests/testLog.cc(%4%) - This is DEBUG 2 - {{x,3}{y,foo}}\n"
"INFO component pattern_stream test_method (tests/testLog.cc:%5%) tests/testLog.cc(%5%) - This is INFO 3 - {{x,3}{y,foo}}\n"
"DEBUG component pattern_stream test_method (tests/testLog.cc:%6%) tests/testLog.cc(%6%) - This is DEBUG 3 - {{x,3}{y,foo}}\n"
"INFO component pattern_stream test_method (tests/testLog.cc:%7%) tests/testLog.cc(%7%) - This is INFO 4 - {{y,foo}}\n"
"DEBUG component pattern_stream test_method (tests/testLog.cc:%8%) tests/testLog.cc(%8%) - This is DEBUG 4 - {{y,foo}}\n"
"INFO root pattern_stream test_method (tests/testLog.cc:%9%) tests/testLog.cc(%9%) - This is INFO 5 - {{y,foo}}\n"
"DEBUG root pattern_stream test_method (tests/testLog.cc:%10%) tests/testLog.cc(%10%) - This is DEBUG 5 - {{y,foo}}\n";
std::vector<std::string> args;

configure(LAYOUT_PATTERN);
Expand Down Expand Up @@ -298,8 +298,8 @@ BOOST_FIXTURE_TEST_CASE(pattern_stream, LogFixture) {
BOOST_FIXTURE_TEST_CASE(MDCPutPid, LogFixture) {

std::string msg;
std::string expected_msg = "INFO root LogFixture pid_log_helper (tests/logTest.cc:%1%) "
"tests/logTest.cc(%1%) - %2% - "
std::string expected_msg = "INFO root LogFixture pid_log_helper (tests/testLog.cc:%1%) "
"tests/testLog.cc(%1%) - %2% - "
"{{" MDC_PID_KEY ",%3%}}\n";
std::vector<std::string> args;
pid_t pid = fork();
Expand Down
65 changes: 44 additions & 21 deletions tests/logTest.py → tests/testLog.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,13 +24,14 @@
This tests the logging system in a variety of ways.
"""

import lsst.log as log
import os
import shutil
import tempfile
import threading
import unittest

import lsst.log as log


class TestLog(unittest.TestCase):

Expand Down Expand Up @@ -203,17 +204,17 @@ def testPattern(self):

# Use format to make line numbers easier to change.
self.check("""
INFO root testPattern (logTest.py:{0[0]}) logTest.py({0[0]}) - This is INFO - {{}}
DEBUG root testPattern (logTest.py:{0[1]}) logTest.py({0[1]}) - This is DEBUG - {{}}
INFO root testPattern (logTest.py:{0[2]}) logTest.py({0[2]}) - This is INFO 2 - {{{{x,3}}{{y,foo}}{{z,<class '{1}.TestLog'>}}}}
DEBUG root testPattern (logTest.py:{0[3]}) logTest.py({0[3]}) - This is DEBUG 2 - {{{{x,3}}{{y,foo}}{{z,<class '{1}.TestLog'>}}}}
INFO component testPattern (logTest.py:{0[4]}) logTest.py({0[4]}) - This is INFO 3 - {{{{x,3}}{{y,foo}}}}
DEBUG component testPattern (logTest.py:{0[5]}) logTest.py({0[5]}) - This is DEBUG 3 - {{{{x,3}}{{y,foo}}}}
INFO component testPattern (logTest.py:{0[6]}) logTest.py({0[6]}) - This is INFO 4 - {{{{y,foo}}}}
DEBUG component testPattern (logTest.py:{0[7]}) logTest.py({0[7]}) - This is DEBUG 4 - {{{{y,foo}}}}
INFO root testPattern (logTest.py:{0[8]}) logTest.py({0[8]}) - This is INFO 5 - {{{{y,foo}}}}
DEBUG root testPattern (logTest.py:{0[9]}) logTest.py({0[9]}) - This is DEBUG 5 - {{{{y,foo}}}}
""".format([x + 177 for x in (0, 1, 8, 9, 14, 15, 18, 19, 22, 23)], __name__))
INFO root testPattern (testLog.py:{0[0]}) testLog.py({0[0]}) - This is INFO - {{}}
DEBUG root testPattern (testLog.py:{0[1]}) testLog.py({0[1]}) - This is DEBUG - {{}}
INFO root testPattern (testLog.py:{0[2]}) testLog.py({0[2]}) - This is INFO 2 - {{{{x,3}}{{y,foo}}{{z,<class '{1}.TestLog'>}}}}
DEBUG root testPattern (testLog.py:{0[3]}) testLog.py({0[3]}) - This is DEBUG 2 - {{{{x,3}}{{y,foo}}{{z,<class '{1}.TestLog'>}}}}
INFO component testPattern (testLog.py:{0[4]}) testLog.py({0[4]}) - This is INFO 3 - {{{{x,3}}{{y,foo}}}}
DEBUG component testPattern (testLog.py:{0[5]}) testLog.py({0[5]}) - This is DEBUG 3 - {{{{x,3}}{{y,foo}}}}
INFO component testPattern (testLog.py:{0[6]}) testLog.py({0[6]}) - This is INFO 4 - {{{{y,foo}}}}
DEBUG component testPattern (testLog.py:{0[7]}) testLog.py({0[7]}) - This is DEBUG 4 - {{{{y,foo}}}}
INFO root testPattern (testLog.py:{0[8]}) testLog.py({0[8]}) - This is INFO 5 - {{{{y,foo}}}}
DEBUG root testPattern (testLog.py:{0[9]}) testLog.py({0[9]}) - This is DEBUG 5 - {{{{y,foo}}}}
""".format([x + 178 for x in (0, 1, 8, 9, 14, 15, 18, 19, 22, 23)], __name__)) # noqa line too long

def testMDCPutPid(self):
"""
Expand Down Expand Up @@ -243,13 +244,13 @@ def testMDCPutPid(self):

with TestLog.StdoutCapture(self.outputFilename):
log.info(msg)
line = 245
line = 246
finally:
log.MDCRemove("PID")

# Use format to make line numbers easier to change.
self.check("""
INFO PID:{1} root testMDCPutPid (logTest.py:{0}) logTest.py({0}) - {2}
INFO PID:{1} root testMDCPutPid (testLog.py:{0}) testLog.py({0}) - {2}
""".format(line, os.getpid(), msg))

# don't pass other tests in child process
Expand Down Expand Up @@ -389,13 +390,35 @@ def testLoggerLevel(self):
logger.fatal("This is FATAL")
logger.info("Format %d %g %s", 3, 2.71828, "foo")
self.check("""
TRACE a.b (logTest.py)- This is TRACE
INFO a.b (logTest.py)- This is INFO
FATAL a.b (logTest.py)- Format 3 2.71828 foo
WARN a.b.c (logTest.py)- This is WARN
ERROR a.b.c (logTest.py)- This is ERROR
FATAL a.b.c (logTest.py)- This is FATAL
INFO a.b.c (logTest.py)- Format 3 2.71828 foo
TRACE a.b (testLog.py)- This is TRACE
INFO a.b (testLog.py)- This is INFO
FATAL a.b (testLog.py)- Format 3 2.71828 foo
WARN a.b.c (testLog.py)- This is WARN
ERROR a.b.c (testLog.py)- This is ERROR
FATAL a.b.c (testLog.py)- This is FATAL
INFO a.b.c (testLog.py)- Format 3 2.71828 foo
""")

def testMsgWithPercentS(self):
"""Test logging messages containing %s (DM-7509)
"""
with TestLog.StdoutCapture(self.outputFilename):
log.configure()
logger = log.Log()
logger.info("INFO with %s")
logger.trace("TRACE with %s")
logger.debug("DEBUG with %s")
logger.warn("WARN with %s")
logger.error("ERROR with %s")
logger.fatal("FATAL with %s")
logger.logMsg(log.DEBUG, "foo", "bar", 5, "DEBUG with %s")
self.check("""
INFO root null - INFO with %s
DEBUG root null - DEBUG with %s
WARN root null - WARN with %s
ERROR root null - ERROR with %s
FATAL root null - FATAL with %s
DEBUG root null - DEBUG with %s
""")


Expand Down