Opened 8 years ago

Closed 8 years ago

Last modified 8 years ago

#1944 closed defect (fixed)

Fix all broken logger format strings

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

Description

Now that #1892 is in master, configure with --enable-logger-checks and fix all logger format strings that you can find, including those reported by make check.

A bug is where the number of placeholders in the logger format string doesn't match the number of arguments passed to it with .arg() calls.

Subtickets

Change History (13)

comment:1 Changed 8 years ago by jelte

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

comment:2 Changed 8 years ago by jreed

An example (from #1989) is:

2012-05-22 05:55:43.129 DEBUG [b10-xfrout.datasrc] DATASRC_DATABASE_FOUND_RRSET search in datasource sqlite3_zone.sqlite3 resulted in RRset foo. 987 IN NS foo.
 @@Missing placeholder %2 for 'foo.'@@ @@Missing placeholder %3 for 'NS'@@ @@Missing placeholder %4 for 'IN'@@
2012-05-22 05:55:43.130 DEBUG [b10-xfrout.datasrc] DATASRC_DATABASE_FIND_RECORDS looking in datasource sqlite3_zone.sqlite3 for record foo./SOA/IN
2012-05-22 05:55:43.131 DEBUG [b10-xfrout.datasrc] DATASRC_DATABASE_FOUND_RRSET search in datasource sqlite3_zone.sqlite3 resulted in RRset foo. 987 IN SOA foo. foo. 102 2 3 4 5
 @@Missing placeholder %2 for 'foo.'@@ @@Missing placeholder %3 for 'SOA'@@ @@Missing placeholder %4 for 'IN'@@
2012-05-22 05:55:43.132 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized

comment:3 Changed 8 years ago by vorner

  • Owner set to vorner
  • Status changed from new to accepted

comment:4 Changed 8 years ago by vorner

  • Owner changed from vorner to UnAssigned
  • Status changed from accepted to reviewing

Hello

The branch is ready for review. But here's the catch:

  • I introduced few tweaks to the strict checking and logging as a whole, to produce less false positives and produce better error messages.
  • The last commit (00472db8fd05a7837e468e9354710cc8be7d0534) on the branch should not go to master and I'll merge the one before that. This one disables some logging completely. This is the infamous function in the database back-end which does some aggregated logging and passes more information to the log system, than the message has placeholders on purpose. This does produce the logger messages with @@Missing placeholder…, and these are the ones in the example. But as we did not reach consensus on this one before, and it would need some more than trivial refactoring of the code, I'd like not to solve this one in this ticket. Should I bring it to the mailing list and create a ticket for it?

Except for the false positives created by python exceptions (now suppressed) and the one aggregate function, I found one message ID that has it wrong and fixed.

Thank you

comment:5 Changed 8 years ago by muks

  • Owner changed from UnAssigned to muks

Picking for review.

comment:6 Changed 8 years ago by muks

  • Owner changed from muks to vorner
  • The code changes look fine.
  • make check fails inside src/lib/python/isc/ddns/ but it looks like the failure is unrelated.
  • This ticket was created separately so that we can start using --enable-logger-checks on our build machines once it was fixed. I think logAndCreateResult() has to be fixed in this bug too. (I gave it 10 points in my estimation.)
  • Lettuce also runs fine, so this ticket is otherwise done.

Regarding logAndCreateResult(), can it not be easily fixed by adding
new message ids, and replacing the logAndCreateResult() call with the
appropriate LOG_XXXX() call + `return (ResultContext?()) ? There seem
to be 5 such calls. Understanding what needs to be logged in each place
can take time though.

comment:7 Changed 8 years ago by vorner

  • Owner changed from vorner to muks

Hello

OK, let's replace the problematic occurrence of the function. I left most of them there, because they were OK, I replaced only one call to the function. Still, I hope I won't be accused of replacing the clever way the logging system was misused to share little bit of code O:-).

About the failure, what was it? I get no failures here, so I'd like to see it at least so I can guess too if it's related.

The code is now in the track1944_2 branch, because I dropped the one temporary commit.

Thanks

comment:8 Changed 8 years ago by muks

  • Owner changed from muks to vorner

Hi vorner

The branch looks good. It can go into master now.

I am not able to reproduce the make check failure under src/lib/python/isc/ddns/. Maybe it was some library version related issue.

comment:9 Changed 8 years ago by muks

Also, when it is pushed into master, please tell Jeremy to enable the configure switch on the build machines so we can start using it. :)

comment:10 Changed 8 years ago by vorner

  • Resolution set to fixed
  • Status changed from reviewing to closed
  • Total Hours changed from 0 to 5.56

Thank you, closing

comment:11 Changed 8 years ago by muks

I see those ddns errors again. They are unrelated, but I'm printing them here for your reference:

make[8]: Entering directory `/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests'
for pytest in session_tests.py zone_config_tests.py ; do \
echo Running test: $pytest ; \
 \
TESTDATA_PATH=/mnt/hayao/src/network/bind10/src/lib/testutils/testdata \
TESTDATA_WRITE_PATH=. \
B10_FROM_BUILD=/mnt/hayao/src/network/bind10 \
PYTHONPATH=/mnt/hayao/src/network/bind10/src/lib/python/isc/log_messages:/mnt/hayao/src/network/bind10/src/lib/python:/mnt/hayao/src/network/bind10/src/lib/python:/mnt/hayao/src/network/bind10/src/lib/dns/python/.libs \
/usr/bin/python3 /mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/$pytest || exit ; \
done
Running test: session_tests.py
EEEEEEEEEEEEEEEEEEEEEEEEEEEEE
======================================================================
ERROR: test_update_acl_check (__main__.SessionACLTest)
Test for various ACL checks.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_update_tsigacl_check (__main__.SessionACLTest)
Test for various ACL checks using TSIG.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_broken_request (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_check_prerequisite_does_not_exist (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_check_prerequisite_exists (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_check_prerequisite_exists_value (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_check_prerequisite_name_in_use (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_check_prerequisite_name_not_in_use (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_check_prerequisites (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_collect_rrsets (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_convert_rrset_class (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_foreach_rr_in_rrset (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_glue_deletions (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_handle (__main__.SessionTest)
Basic update case
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_prerequisite_notzone (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_prerequisites_formerr (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_prescan (__main__.SessionTest)
Test whether the prescan succeeds on data that is ok, and whether
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_prescan_failures (__main__.SessionTest)
Test whether prescan fails on bad data
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_uncaught_exception (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_update_add_delete_rrset (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_update_add_new_data (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_update_add_new_data_interspersed (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_update_apex_special_cases (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_update_bad_class (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_update_cname_special_cases (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_update_delete_name (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_update_delete_normal_rrset_at_apex (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_update_notauth (__main__.SessionTest)
Update attempt for non authoritative zones
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

======================================================================
ERROR: test_update_secondary (__main__.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests/session_tests.py", line 110, in setUp
    REQUEST_LOADER.load([{"action": "ACCEPT"}])}
TypeError: unhashable type: 'pydnspp.Name'

----------------------------------------------------------------------
Ran 29 tests in 0.060s

FAILED (errors=29)
make[8]: *** [check-local] Error 1
make[8]: Leaving directory `/mnt/hayao/src/network/bind10/src/lib/python/isc/ddns/tests'

comment:12 follow-up: Changed 8 years ago by muks

I think it happens due to a library version discrepancy.

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

Replying to muks:

I think it happens due to a library version discrepancy.

You'll need to update libdns++ and its python wrapper (or if the test
environment refers to some older installed versions of these, you'll
need to fix it somehow).

In any case, I think it should be okay for our buildbots.

Note: See TracTickets for help on using tickets.