Skip to content
This repository

Module Level Logging #49

Closed
wants to merge 2 commits into from

1 participant

Jason Buckner
Jason Buckner

All of the logging was using logging.warn(), calling the logging library directly. This caused the logs to be logged to the root logger, thereby making it difficult to selectively filter the logs it produced.

I added log = logging.getLogger(__name__) to each logging file and changed the logging statements to log.{LOG LEVEL}("message") so they'd log to the appropriate logger.

I also cleaned up some of the logging.

Jason Buckner jbuckner closed this
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Showing 2 unique commits by 2 authors.

Nov 05, 2012
Jason Buckner Merge pull request #1 from openid/master
Python OpenID Server Logging and Updates
31dd144
Nov 06, 2012
Jason Buckner change from root-level logging to module-level logging so we can filt…
…er appropriately
73b70a4
This page is out of date. Refresh to see the latest.
13  background-associations.txt
@@ -71,21 +71,24 @@ could make the background fetcher listen for inserts into the queue.
71 71
 
72 72
 The background fetcher needs to do something similar to the following::
73 73
 
  74
+  import logging
  75
+  log = logging.getLogger(__name__)
  76
+
74 77
   def refresh(consumer, endpoint):
75 78
       if consumer.store.getAssociation(endpoint.server_url):
76  
-          logging.info("We don't need to associate with %r", endpoint.server_url)
  79
+          log.info("We don't need to associate with %r" % endpoint.server_url)
77 80
           return
78 81
 
79  
-      logging.info("Associating with %r", endpoint.server_url)
  82
+      log.info("Associating with %r" % endpoint.server_url)
80 83
       now = time.time()
81 84
       assoc = consumer._negotiateAssociation(endpoint)
82 85
       if assoc:
83 86
           elapsed = time.time() - now
84  
-          logging.info('(%0.2f seconds) Associated with %r', elapsed,
85  
-                       endpoint.server_url)
  87
+          log.info('(%0.2f seconds) Associated with %r' % (elapsed,
  88
+                       endpoint.server_url))
86 89
           consumer.store.storeAssociation(endpoint.server_url, assoc)
87 90
       else:
88  
-          logging.error('Failed to make an association with %r',
  91
+          log.error('Failed to make an association with %r' %
89 92
                         endpoint.server_url)
90 93
 
91 94
 The code in this example logs the amount of time that the association
65  openid/consumer/consumer.py
@@ -213,6 +213,7 @@
213 213
            'SUCCESS', 'FAILURE', 'CANCEL', 'SETUP_NEEDED',
214 214
            ]
215 215
 
  216
+log = logging.getLogger(__name__)
216 217
 
217 218
 def makeKVPost(request_message, server_url):
218 219
     """Make a Direct Request to an OpenID Provider and return the
@@ -663,7 +664,7 @@ def _checkReturnTo(self, message, return_to):
663 664
         try:
664 665
             self._verifyReturnToArgs(message.toPostArgs())
665 666
         except ProtocolError, why:
666  
-            logging.exception("Verifying return_to arguments: %s" % (why[0],))
  667
+            log.exception("Verifying return_to arguments: %s" % why[0])
667 668
             return False
668 669
 
669 670
         # Check the return_to base URL against the one in the message.
@@ -729,7 +730,7 @@ def _doIdRes(self, message, endpoint, return_to):
729 730
 
730 731
         # Verify discovery information:
731 732
         endpoint = self._verifyDiscoveryResults(message, endpoint)
732  
-        logging.info("Received id_res response from %s using association %s" %
  733
+        log.info("Received id_res response from %s using association %s" %
733 734
                     (endpoint.server_url,
734 735
                      message.getArg(OPENID_NS, 'assoc_handle')))
735 736
 
@@ -923,7 +924,7 @@ def _verifyDiscoveryResultsOpenID2(self, resp_msg, endpoint):
923 924
         # endpoints and responses that didn't match the original
924 925
         # request.
925 926
         if not endpoint:
926  
-            logging.info('No pre-discovered information supplied.')
  927
+            log.info('No pre-discovered information supplied.')
927 928
             endpoint = self._discoverAndVerify(to_match.claimed_id, [to_match])
928 929
         else:
929 930
             # The claimed ID matches, so we use the endpoint that we
@@ -932,10 +933,9 @@ def _verifyDiscoveryResultsOpenID2(self, resp_msg, endpoint):
932 933
             try:
933 934
                 self._verifyDiscoverySingle(endpoint, to_match)
934 935
             except ProtocolError, e:
935  
-                logging.exception(
936  
-                    "Error attempting to use stored discovery information: " +
937  
-                    str(e))
938  
-                logging.info("Attempting discovery to verify endpoint")
  936
+                log.exception(
  937
+                    "Error attempting to use stored discovery information: %s" % str(e))
  938
+                log.info("Attempting discovery to verify endpoint")
939 939
                 endpoint = self._discoverAndVerify(
940 940
                     to_match.claimed_id, [to_match])
941 941
 
@@ -977,9 +977,9 @@ def _verifyDiscoveryResultsOpenID1(self, resp_msg, endpoint):
977 977
                 except TypeURIMismatch:
978 978
                     self._verifyDiscoverySingle(endpoint, to_match_1_0)
979 979
             except ProtocolError, e:
980  
-                logging.exception("Error attempting to use stored discovery information: " +
981  
-                            str(e))
982  
-                logging.info("Attempting discovery to verify endpoint")
  980
+                log.exception(
  981
+                    "Error attempting to use stored discovery information: %s" % str(e))
  982
+                log.info("Attempting discovery to verify endpoint")
983 983
             else:
984 984
                 return endpoint
985 985
 
@@ -1049,7 +1049,7 @@ def _discoverAndVerify(self, claimed_id, to_match_endpoints):
1049 1049
 
1050 1050
         @raises DiscoveryFailure: when discovery fails.
1051 1051
         """
1052  
-        logging.info('Performing discovery on %s' % (claimed_id,))
  1052
+        log.info('Performing discovery on %s' % (claimed_id,))
1053 1053
         _, services = self._discover(claimed_id)
1054 1054
         if not services:
1055 1055
             raise DiscoveryFailure('No OpenID information found at %s' %
@@ -1076,10 +1076,10 @@ def _verifyDiscoveredServices(self, claimed_id, services, to_match_endpoints):
1076 1076
                     # succeeded. Return this endpoint.
1077 1077
                     return endpoint
1078 1078
         else:
1079  
-            logging.error('Discovery verification failure for %s' %
  1079
+            log.error('Discovery verification failure for %s' %
1080 1080
                         (claimed_id,))
1081 1081
             for failure_message in failure_messages:
1082  
-                logging.error(' * Endpoint mismatch: ' + failure_message)
  1082
+                log.error(' * Endpoint mismatch: %s' % failure_message)
1083 1083
 
1084 1084
             raise DiscoveryFailure(
1085 1085
                 'No matching endpoint found after discovering %s'
@@ -1091,14 +1091,14 @@ def _checkAuth(self, message, server_url):
1091 1091
         @returns: True if the request is valid.
1092 1092
         @rtype: bool
1093 1093
         """
1094  
-        logging.info('Using OpenID check_authentication')
  1094
+        log.info('Using OpenID check_authentication')
1095 1095
         request = self._createCheckAuthRequest(message)
1096 1096
         if request is None:
1097 1097
             return False
1098 1098
         try:
1099 1099
             response = self._makeKVPost(request, server_url)
1100 1100
         except (fetchers.HTTPFetchingError, ServerError), e:
1101  
-            logging.exception('check_authentication failed: %s' % (e[0],))
  1101
+            log.exception('check_authentication failed: %s' % e[0])
1102 1102
             return False
1103 1103
         else:
1104 1104
             return self._processCheckAuthResponse(response, server_url)
@@ -1110,12 +1110,12 @@ def _createCheckAuthRequest(self, message):
1110 1110
         signed = message.getArg(OPENID_NS, 'signed')
1111 1111
         if signed:
1112 1112
             for k in signed.split(','):
1113  
-                logging.info(k)
  1113
+                log.info(k)
1114 1114
                 val = message.getAliasedArg(k)
1115 1115
 
1116 1116
                 # Signed value is missing
1117 1117
                 if val is None:
1118  
-                    logging.info('Missing signed field %r' % (k,))
  1118
+                    log.info('Missing signed field %r' % k)
1119 1119
                     return None
1120 1120
 
1121 1121
         check_auth_message = message.copy()
@@ -1130,10 +1130,10 @@ def _processCheckAuthResponse(self, response, server_url):
1130 1130
 
1131 1131
         invalidate_handle = response.getArg(OPENID_NS, 'invalidate_handle')
1132 1132
         if invalidate_handle is not None:
1133  
-            logging.info(
1134  
-                'Received "invalidate_handle" from server %s' % (server_url,))
  1133
+            log.info(
  1134
+                'Received "invalidate_handle" from server %s' % server_url)
1135 1135
             if self.store is None:
1136  
-                logging.error('Unexpectedly got invalidate_handle without '
  1136
+                log.error('Unexpectedly got invalidate_handle without '
1137 1137
                             'a store!')
1138 1138
             else:
1139 1139
                 self.store.removeAssociation(server_url, invalidate_handle)
@@ -1141,7 +1141,7 @@ def _processCheckAuthResponse(self, response, server_url):
1141 1141
         if is_valid == 'true':
1142 1142
             return True
1143 1143
         else:
1144  
-            logging.error('Server responds that checkAuth call is not valid')
  1144
+            log.error('Server responds that checkAuth call is not valid')
1145 1145
             return False
1146 1146
 
1147 1147
     def _getAssociation(self, endpoint):
@@ -1194,7 +1194,7 @@ def _negotiateAssociation(self, endpoint):
1194 1194
                 except ServerError, why:
1195 1195
                     # Do not keep trying, since it rejected the
1196 1196
                     # association type that it told us to use.
1197  
-                    logging.error('Server %s refused its suggested association '
  1197
+                    log.error('Server %s refused its suggested association '
1198 1198
                                 'type: session_type=%s, assoc_type=%s'
1199 1199
                                 % (endpoint.server_url, session_type,
1200 1200
                                    assoc_type))
@@ -1217,7 +1217,7 @@ def _extractSupportedAssociationType(self, server_error, endpoint,
1217 1217
         # should be considered a total failure.
1218 1218
         if server_error.error_code != 'unsupported-type' or \
1219 1219
                server_error.message.isOpenID1():
1220  
-            logging.error(
  1220
+            log.error(
1221 1221
                 'Server error when requesting an association from %r: %s'
1222 1222
                 % (endpoint.server_url, server_error.error_text))
1223 1223
             return None
@@ -1225,7 +1225,7 @@ def _extractSupportedAssociationType(self, server_error, endpoint,
1225 1225
         # The server didn't like the association/session type
1226 1226
         # that we sent, and it sent us back a message that
1227 1227
         # might tell us how to handle it.
1228  
-        logging.error(
  1228
+        log.error(
1229 1229
             'Unsupported association type %s: %s' % (assoc_type,
1230 1230
                                                      server_error.error_text,))
1231 1231
 
@@ -1235,13 +1235,13 @@ def _extractSupportedAssociationType(self, server_error, endpoint,
1235 1235
         session_type = server_error.message.getArg(OPENID_NS, 'session_type')
1236 1236
 
1237 1237
         if assoc_type is None or session_type is None:
1238  
-            logging.error('Server responded with unsupported association '
  1238
+            log.error('Server responded with unsupported association '
1239 1239
                         'session but did not supply a fallback.')
1240 1240
             return None
1241 1241
         elif not self.negotiator.isAllowed(assoc_type, session_type):
1242 1242
             fmt = ('Server sent unsupported session/association type: '
1243 1243
                    'session_type=%s, assoc_type=%s')
1244  
-            logging.error(fmt % (session_type, assoc_type))
  1244
+            log.error(fmt % (session_type, assoc_type))
1245 1245
             return None
1246 1246
         else:
1247 1247
             return assoc_type, session_type
@@ -1262,17 +1262,17 @@ def _requestAssociation(self, endpoint, assoc_type, session_type):
1262 1262
         try:
1263 1263
             response = self._makeKVPost(args, endpoint.server_url)
1264 1264
         except fetchers.HTTPFetchingError, why:
1265  
-            logging.exception('openid.associate request failed: %s' % (why[0],))
  1265
+            log.exception('openid.associate request failed: %s' % why[0])
1266 1266
             return None
1267 1267
 
1268 1268
         try:
1269 1269
             assoc = self._extractAssociation(response, assoc_session)
1270 1270
         except KeyError, why:
1271  
-            logging.exception('Missing required parameter in response from %s: %s'
  1271
+            log.exception('Missing required parameter in response from %s: %s'
1272 1272
                         % (endpoint.server_url, why[0]))
1273 1273
             return None
1274 1274
         except ProtocolError, why:
1275  
-            logging.exception('Protocol error parsing response from %s: %s' % (
  1275
+            log.exception('Protocol error parsing response from %s: %s' % (
1276 1276
                 endpoint.server_url, why[0]))
1277 1277
             return None
1278 1278
         else:
@@ -1349,8 +1349,7 @@ def _getOpenID1SessionType(self, assoc_response):
1349 1349
         # OpenID 1, but we'll accept it anyway, while issuing a
1350 1350
         # warning.
1351 1351
         if session_type == 'no-encryption':
1352  
-            logging.warn('OpenID server sent "no-encryption"'
1353  
-                        'for OpenID 1.X')
  1352
+            log.warn('OpenID server sent "no-encryption" for OpenID 1.X')
1354 1353
 
1355 1354
         # Missing or empty session type is the way to flag a
1356 1355
         # 'no-encryption' response. Change the session type to
@@ -1600,7 +1599,7 @@ def getMessage(self, realm, return_to=None, immediate=False):
1600 1599
         else:
1601 1600
             assoc_log_msg = 'using stateless mode.'
1602 1601
 
1603  
-        logging.info("Generated %s request to %s %s" %
  1602
+        log.info("Generated %s request to %s %s" %
1604 1603
                     (mode, self.endpoint.server_url, assoc_log_msg))
1605 1604
 
1606 1605
         return message
@@ -1780,7 +1779,7 @@ def getSignedNS(self, ns_uri):
1780 1779
 
1781 1780
         for key in msg_args.iterkeys():
1782 1781
             if not self.isSigned(ns_uri, key):
1783  
-                logging.info("SuccessResponse.getSignedNS: (%s, %s) not signed."
  1782
+                log.info("SuccessResponse.getSignedNS: (%s, %s) not signed."
1784 1783
                             % (ns_uri, key))
1785 1784
                 return None
1786 1785
 
4  openid/consumer/discover.py
@@ -37,6 +37,8 @@
37 37
 from openid.message import OPENID1_NS as OPENID_1_0_MESSAGE_NS
38 38
 from openid.message import OPENID2_NS as OPENID_2_0_MESSAGE_NS
39 39
 
  40
+log = logging.getLogger(__name__)
  41
+
40 42
 class OpenIDServiceEndpoint(object):
41 43
     """Object representing an OpenID service endpoint.
42 44
 
@@ -426,7 +428,7 @@ def discoverXRI(iname):
426 428
         for service_element in services:
427 429
             endpoints.extend(flt.getServiceEndpoints(iname, service_element))
428 430
     except XRDSError:
429  
-        logging.exception('xrds error on ' + iname)
  431
+        log.exception('xrds error on %s' % iname)
430 432
 
431 433
     for endpoint in endpoints:
432 434
         # Is there a way to pass this through the filter to the endpoint
4  openid/extensions/sreg.py
@@ -69,6 +69,8 @@
69 69
     'timezone':'Time Zone',
70 70
     }
71 71
 
  72
+log = logging.getLogger(__name__)
  73
+
72 74
 def checkFieldName(field_name):
73 75
     """Check to see that the given value is a valid simple
74 76
     registration data field name.
@@ -95,7 +97,7 @@ def checkFieldName(field_name):
95 97
 try:
96 98
     registerNamespaceAlias(ns_uri_1_1, 'sreg')
97 99
 except NamespaceAliasRegistrationError, e:
98  
-    logging.exception('registerNamespaceAlias(%r, %r) failed: %s' % (ns_uri_1_1,
  100
+    log.exception('registerNamespaceAlias(%r, %r) failed: %s' % (ns_uri_1_1,
99 101
                                                                'sreg', str(e),))
100 102
 
101 103
 def supportsSReg(endpoint):
6  openid/kvform.py
@@ -3,6 +3,8 @@
3 3
 import types
4 4
 import logging
5 5
 
  6
+log = logging.getLogger(__name__)
  7
+
6 8
 class KVFormError(ValueError):
7 9
     pass
8 10
 
@@ -21,7 +23,7 @@ def err(msg):
21 23
         if strict:
22 24
             raise KVFormError(formatted)
23 25
         else:
24  
-            logging.warn(formatted)
  26
+            log.warn(formatted)
25 27
 
26 28
     lines = []
27 29
     for k, v in seq:
@@ -72,7 +74,7 @@ def err(msg):
72 74
         if strict:
73 75
             raise KVFormError(formatted)
74 76
         else:
75  
-            logging.warn(formatted)
  77
+            log.warn(formatted)
76 78
 
77 79
     lines = data.split('\n')
78 80
     if lines[-1]:
15  openid/oidutil.py
@@ -8,8 +8,6 @@
8 8
 __all__ = ['log', 'appendArgs', 'toBase64', 'fromBase64', 'autoSubmitHTML', 'toUnicode']
9 9
 
10 10
 import binascii
11  
-import sys
12  
-import urlparse
13 11
 import logging
14 12
 
15 13
 from urllib import urlencode
@@ -22,6 +20,8 @@
22 20
     'elementtree.ElementTree',
23 21
     ]
24 22
 
  23
+log = logging.getLogger(__name__)
  24
+
25 25
 def toUnicode(value):
26 26
     """Returns the given argument as a unicode object.
27 27
 
@@ -73,13 +73,14 @@ def importElementTree(module_names=None):
73 73
             pass
74 74
         else:
75 75
             # Make sure it can actually parse XML
  76
+            xml_test = '<unused/>'
76 77
             try:
77  
-                ElementTree.XML('<unused/>')
  78
+                ElementTree.XML(xml_test)
78 79
             except (SystemExit, MemoryError, AssertionError):
79 80
                 raise
80 81
             except:
81  
-                logging.exception('Not using ElementTree library %r because it failed to '
82  
-                    'parse a trivial document: %s' % mod_name)
  82
+                log.exception('Not using ElementTree library %r because it failed to '
  83
+                    'parse a trivial document: %s' % (mod_name, xml_test))
83 84
             else:
84 85
                 return ElementTree
85 86
     else:
@@ -91,7 +92,7 @@ def importElementTree(module_names=None):
91 92
 def log(message, level=0):
92 93
     """Handle a log message from the OpenID library.
93 94
 
94  
-    This is a legacy function which redirects to logging.error.
  95
+    This is a legacy function which redirects to log.error.
95 96
     The logging module should be used instead of this
96 97
 
97 98
     @param message: A string containing a debugging message from the
@@ -106,7 +107,7 @@ def log(message, level=0):
106 107
     @returns: Nothing.
107 108
     """
108 109
 
109  
-    logging.error("This is a legacy log message, please use the "
  110
+    log.error("This is a legacy log message, please use the "
110 111
       "logging module. Message: %s", message)
111 112
 
112 113
 def appendArgs(url, args):
15  openid/server/server.py
@@ -143,6 +143,8 @@
143 143
 
144 144
 UNUSED = None
145 145
 
  146
+log = logging.getLogger(__name__)
  147
+
146 148
 class OpenIDRequest(object):
147 149
     """I represent an incoming OpenID request.
148 150
 
@@ -421,8 +423,8 @@ def fromMessage(klass, message, op_endpoint=UNUSED):
421 423
         if message.isOpenID1():
422 424
             session_type = message.getArg(OPENID_NS, 'session_type')
423 425
             if session_type == 'no-encryption':
424  
-                logging.warn('Received OpenID 1 request with a no-encryption '
425  
-                            'assocaition session type. Continuing anyway.')
  426
+                log.warn('Received OpenID 1 request with a no-encryption '
  427
+                            'association session type. Continuing anyway.')
426 428
             elif not session_type:
427 429
                 session_type = 'no-encryption'
428 430
         else:
@@ -1171,15 +1173,14 @@ def verify(self, assoc_handle, message):
1171 1173
         """
1172 1174
         assoc = self.getAssociation(assoc_handle, dumb=True)
1173 1175
         if not assoc:
1174  
-            logging.error("failed to get assoc with handle %r to verify "
1175  
-                        "message %r"
1176  
-                        % (assoc_handle, message))
  1176
+            log.error("failed to get assoc with handle %r to verify "
  1177
+                        "message %r" % (assoc_handle, message))
1177 1178
             return False
1178 1179
 
1179 1180
         try:
1180 1181
             valid = assoc.checkMessageSignature(message)
1181 1182
         except ValueError, ex:
1182  
-            logging.exception("Error in verifying %s with %s: %s" % (message,
  1183
+            log.exception("Error in verifying %s with %s: %s" % (message,
1183 1184
                                                                assoc,
1184 1185
                                                                ex))
1185 1186
             return False
@@ -1286,7 +1287,7 @@ def getAssociation(self, assoc_handle, dumb, checkExpiration=True):
1286 1287
             key = self._normal_key
1287 1288
         assoc = self.store.getAssociation(key, assoc_handle)
1288 1289
         if assoc is not None and assoc.expiresIn <= 0:
1289  
-            logging.info("requested %sdumb key %r is expired (by %s seconds)" %
  1290
+            log.info("requested %sdumb key %r is expired (by %s seconds)" %
1290 1291
                         ((not dumb) and 'not-' or '',
1291 1292
                          assoc_handle, assoc.expiresIn))
1292 1293
             if checkExpiration:
6  openid/server/trustroot.py
@@ -24,6 +24,8 @@
24 24
 import re
25 25
 import logging
26 26
 
  27
+log = logging.getLogger(__name__)
  28
+
27 29
 ############################################
28 30
 _protocols = ['http', 'https']
29 31
 _top_level_domains = [
@@ -443,12 +445,12 @@ def verifyReturnTo(realm_str, return_to, _vrfy=getAllowedReturnURLs):
443 445
     try:
444 446
         allowable_urls = _vrfy(realm.buildDiscoveryURL())
445 447
     except RealmVerificationRedirected, err:
446  
-        logging.exception(str(err))
  448
+        log.exception(str(err))
447 449
         return False
448 450
 
449 451
     if returnToMatches(allowable_urls, return_to):
450 452
         return True
451 453
     else:
452  
-        logging.error("Failed to validate return_to %r for realm %r, was not "
  454
+        log.error("Failed to validate return_to %r for realm %r, was not "
453 455
                     "in %s" % (return_to, realm_str, allowable_urls))
454 456
         return False
4  openid/store/filestore.py
@@ -59,6 +59,8 @@ def mkstemp(dir):
59 59
 else:
60 60
     _isFilenameSafe = set(_filename_allowed).__contains__
61 61
 
  62
+log = logging.getLogger(__name__)
  63
+
62 64
 def _safe64(s):
63 65
     h64 = oidutil.toBase64(cryptutil.sha1(s))
64 66
     h64 = h64.replace('+', '_')
@@ -372,7 +374,7 @@ def _allAssocs(self):
372 374
                 association_file = file(association_filename, 'rb')
373 375
             except IOError, why:
374 376
                 if why.errno == ENOENT:
375  
-                    logging.exception("%s disappeared during %s._allAssocs" % (
  377
+                    log.exception("%s disappeared during %s._allAssocs" % (
376 378
                         association_filename, self.__class__.__name__))
377 379
                 else:
378 380
                     raise
Commit_comment_tip

Tip: You can add notes to lines in a file. Hover to the left of a line to make a note

Something went wrong with that request. Please try again.