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.

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

Change logging exception to logging error, at least for HTTPErrors #835

2 changes: 1 addition & 1 deletion ezidapp/admin.py
Original file line number Diff line number Diff line change
Expand Up @@ -494,7 +494,7 @@ def save_model(self, request, obj, form, change):
)
except Exception as e:
if django.conf.settings.DEBUG:
logging.exception('#' * 100)
logging.error('#' * 100)

django.contrib.messages.error(
request, "Error sending status change email: " + str(e)
Expand Down
2 changes: 1 addition & 1 deletion ezidapp/management/commands/diag-create-missing-minters.py
Original file line number Diff line number Diff line change
Expand Up @@ -61,7 +61,7 @@ def handle(self, *_, **opt):
if django.conf.settings.DEBUG:
import logging

logging.exception('#' * 100)
logging.error('#' * 100)
if opt.debug:
raise
raise django.core.management.CommandError(
Expand Down
6 changes: 3 additions & 3 deletions ezidapp/management/commands/link-checker-by-ids.py
Original file line number Diff line number Diff line change
Expand Up @@ -244,7 +244,7 @@ def check_url_0(self, target):
mimeType = c.info().get("Content-Type", "unknown")
content = c.read(django.conf.settings.LINKCHECKER_MAX_READ)
except http.client.IncompleteRead as e:
log.exception('http.client.IncompleteRead')
log.error('http.client.IncompleteRead')
# Some servers deliver a complete HTML document, but,
# apparently expecting further requests from a web browser
# that never arrive, hold the connection open and ultimately
Expand All @@ -261,12 +261,12 @@ def check_url_0(self, target):
returnCode = -1
error = "IncompleteRead: " + str(e)[:200]
except urllib.error.HTTPError as e:
log.exception('HTTPError')
log.error('HTTPError')
success = False
returnCode = e.code
error = "HTTPError: " + str(e)[:200]
except Exception as e:
log.exception('Exception')
log.error('Exception')
success = False
returnCode = -1
error = "Exception: " + str(e)[:200]
Expand Down
16 changes: 8 additions & 8 deletions ezidapp/management/commands/proc-crossref.py
Original file line number Diff line number Diff line change
Expand Up @@ -77,7 +77,7 @@ def run(self):
task_model.status = self.queue.IGNORED
except Exception as e:
log.error('#' * 100)
log.exception(f'Exception when handling task "{task_model}"')
log.error(f'Exception when handling task "{task_model}"')
task_model.error = str(e)
# if self.is_permanent_error(e):
if True:
Expand Down Expand Up @@ -247,19 +247,19 @@ def _submitDeposit(self, deposit: str, batchId: str, doi: str) -> bool:
'unexpected return from metadata submission: ' + r
)
except urllib.error.HTTPError as e:
log.exception('HTTPError')
log.error('HTTPError')
msg = None
if e.fp is not None:
try:
msg = e.fp.read().decode('utf-8')
except Exception:
log.exception('Exception')
log.error('Exception')
raise Exception(msg) from e
finally:
if c:
c.close()
except Exception as e:
log.exception('Exception')
log.error('Exception')
impl.log.otherError(
'crossref._submitDeposit',
self._wrapException(f'error submitting deposit, doi {doi}, batch {batchId}', e),
Expand Down Expand Up @@ -413,13 +413,13 @@ def _checkDepositStatus(self, task_model: ezidapp.models.async_queue.CrossrefQue
)
response = c.read()
except urllib.error.HTTPError as e:
log.exception('HTTPError')
log.error('HTTPError')
msg = None
if e.fp is not None:
try:
msg = e.fp.read().decode('utf-8')
except Exception:
log.exception('Exception')
log.error('Exception')
raise Exception(msg) from e
finally:
if c:
Expand All @@ -430,7 +430,7 @@ def _checkDepositStatus(self, task_model: ezidapp.models.async_queue.CrossrefQue
# the embedded encoding declaration.
root = lxml.etree.XML(response)
except Exception as e:
log.exception('Exception')
log.error('Exception')
assert False, 'XML parse error: ' + str(e)

assert root.tag == 'doi_batch_diagnostic', 'unexpected response root element: ' + root.tag
Expand Down Expand Up @@ -504,7 +504,7 @@ def _sendEmail(self, emailAddress: str, task_model: ezidapp.models.async_queue.C
subject_str, body_str, from_str, [to_str], fail_silently=True
)
except Exception as e:
log.exception('Exception')
log.error('Exception')
raise self._wrapException('error sending email', e)

def _wrapException(self, context, exception):
Expand Down
20 changes: 10 additions & 10 deletions ezidapp/management/commands/proc-download.py
Original file line number Diff line number Diff line change
Expand Up @@ -80,7 +80,7 @@ def run(self):
# Don't sleep while work is in progress
doSleep = False
except Exception as e:
self.log.exception('Exception')
self.log.error('Exception')
impl.log.otherError("download.run", e)
doSleep = True

Expand Down Expand Up @@ -170,7 +170,7 @@ def _createFile(self, r: ezidapp.models.async_queue.DownloadQueue):
# probe the file to find its size.
n = f.tell()
except Exception as e:
self.log.exception('Exception')
self.log.error('Exception')
raise self._wrapException("error creating file", e)
else:
# This is run if there's no exception thrown
Expand Down Expand Up @@ -315,7 +315,7 @@ def _harvest1(self, r: ezidapp.models.async_queue.DownloadQueue, f: typing.TextI
_total += 1
self._flushFile(f)
except Exception as e:
self.log.exception('Exception')
self.log.error('Exception')
raise self._wrapException("error writing file", e)
r.lastId = ids[-1].identifier
r.fileSize = f.tell()
Expand All @@ -334,7 +334,7 @@ def _harvest(self, r: ezidapp.models.async_queue.DownloadQueue):
f.seek(r.fileSize)
f.truncate()
except Exception as e:
self.log.exception('Exception')
self.log.error('Exception')
raise self._wrapException("error re-opening/seeking/truncating file", e)
start = r.currentIndex
for i in range(r.currentIndex, len(r.toHarvest.split(","))):
Expand All @@ -348,7 +348,7 @@ def _harvest(self, r: ezidapp.models.async_queue.DownloadQueue):
f.write("</records>")
self._flushFile(f)
except Exception as e:
self.log.exception('Exception')
self.log.error('Exception')
raise self._wrapException("error writing file footer", e)
r.stage = ezidapp.models.async_queue.DownloadQueue.COMPRESS
r.save()
Expand Down Expand Up @@ -399,7 +399,7 @@ def _compressFile(self, r: ezidapp.models.async_queue.DownloadQueue):
p.returncode == 0 and stderr == b''
), f"compression command returned status code {p.returncode:d}, stderr '{stderr}'"
except Exception as e:
self.log.exception('Exception')
self.log.error('Exception')
raise self._wrapException("error compressing file", e)
else:
r.stage = ezidapp.models.async_queue.DownloadQueue.DELETE
Expand All @@ -415,7 +415,7 @@ def _deleteUncompressedFile(self, r: ezidapp.models.async_queue.DownloadQueue):
if os.path.exists(self._path(r, 1)):
os.unlink(self._path(r, 1))
except Exception as e:
self.log.exception('Exception')
self.log.error('Exception')
raise self._wrapException("error deleting uncompressed file", e)
else:
r.stage = ezidapp.models.async_queue.DownloadQueue.MOVE
Expand All @@ -432,7 +432,7 @@ def _moveCompressedFile(self, r: ezidapp.models.async_queue.DownloadQueue):
else:
assert os.path.exists(self._path(r, 3)), "file has disappeared"
except Exception as e:
self.log.exception('Exception')
self.log.error('Exception')
raise self._wrapException("error moving compressed file", e)
else:
r.stage = ezidapp.models.async_queue.DownloadQueue.NOTIFY
Expand All @@ -444,7 +444,7 @@ def _notifyRequestor(self, r: ezidapp.models.async_queue.DownloadQueue):
f = open(self._path(r, 4), mode="w", encoding="utf-8")
f.write(f"{ezidapp.models.util.getUserByPid(r.requestor).username}\n{r.rawRequest}\n")
except Exception as e:
self.log.exception('Exception')
self.log.error('Exception')
raise self._wrapException("error writing sidecar file", e)
finally:
if f:
Expand Down Expand Up @@ -475,7 +475,7 @@ def _notifyRequestor(self, r: ezidapp.models.async_queue.DownloadQueue):
fail_silently=True,
)
except Exception as e:
self.log.exception('Exception')
self.log.error('Exception')
raise self._wrapException("error sending email", e)
r.delete()

Expand Down
6 changes: 3 additions & 3 deletions ezidapp/management/commands/proc-link-checker-update.py
Original file line number Diff line number Diff line change
Expand Up @@ -107,14 +107,14 @@ def run(self):
has_issues=si2.hasIssues,
update_time=si2.updateTime)
except ezidapp.models.identifier.SearchIdentifier.DoesNotExist:
log.exception('SearchIdentifier.DoesNotExist')
log.error('SearchIdentifier.DoesNotExist')
except opensearchpy.exceptions.OpenSearchException as e:
log.exception('OpenSearchException in link checker', e)
log.error('OpenSearchException in link checker', e)

si = next(siGenerator)

except Exception as e:
log.exception('Exception')
log.error('Exception')
impl.log.otherError("linkcheck_update._linkcheckUpdateDaemon", e)

siGenerator = lcGenerator = si = lc = si2 = None
Expand Down
27 changes: 20 additions & 7 deletions ezidapp/management/commands/proc-link-checker.py
Original file line number Diff line number Diff line change
Expand Up @@ -88,6 +88,19 @@
import ezidapp.models.user
import impl
import impl.util
import traceback

def simple_error(e):
"""Extracts the exception name, HTTP status code (if applicable), filename, and line number."""
tb = traceback.extract_tb(e.__traceback__)[0] # Get last traceback entry
error_msg = f"{type(e).__name__} in {tb.filename} at line {tb.lineno}"

# If it's an HTTPError, include the status code
if isinstance(e, urllib.error.HTTPError):
error_msg += f" (HTTP {e.code})"

return error_msg


log = logging.getLogger(__name__)
_lock = threading.Lock()
Expand Down Expand Up @@ -239,7 +252,7 @@ def loadExclusionFile(self):
try:
user, flag = l.split()
except ValueError:
log.exception('ValueError')
log.error('ValueError')
assert False, "syntax error on line %d" % n
assert flag in ["permanent", "temporary"], "syntax error on line %d" % n

Expand All @@ -250,14 +263,14 @@ def loadExclusionFile(self):
ezidapp.models.user.User.objects.get(username=user).id
)
except ezidapp.models.user.User.DoesNotExist:
log.exception('User.DoesNotExist')
log.error('User.DoesNotExist')
assert False, "no such user: " + user
_permanentExcludes = pe
_temporaryExcludes = te
_exclusionFileModifyTime = s.st_mtime
log.info("exclusion file successfully loaded")
except Exception as e:
log.exception('Exception')
log.error('Exception')
if s is not None:
_exclusionFileModifyTime = s.st_mtime
log.error("error loading exclusion file: " + str(e))
Expand Down Expand Up @@ -561,7 +574,7 @@ def worker(self):
mimeType = c.info().get("Content-Type", "unknown")
content = c.read(django.conf.settings.LINKCHECKER_MAX_READ)
except http.client.IncompleteRead as e:
log.exception('http.client.IncompleteRead')
log.error('http.client.IncompleteRead')
# Some servers deliver a complete HTML document, but,
# apparently expecting further requests from a web browser
# that never arrive, hold the connection open and ultimately
Expand All @@ -578,11 +591,11 @@ def worker(self):
returnCode = -1
lc.checkFailed(returnCode, impl.util.formatException(e))
except urllib.error.HTTPError as e:
log.exception('HTTPError')
log.error(simple_error(e))
success = False
returnCode = e.code
except Exception as e:
log.exception('Exception')
log.error(simple_error(e))
success = False
returnCode = -1
lc.checkFailed(returnCode, impl.util.formatException(e))
Expand All @@ -605,7 +618,7 @@ def worker(self):
self.markLinkChecked(index)

except Exception as e:
log.exception('Exception: ' + str(e))
log.error(f"Exception: \n{simple_error(e)}")


class OwnerWorkset(Command):
Expand Down
2 changes: 1 addition & 1 deletion ezidapp/management/commands/proc-newsfeed.py
Original file line number Diff line number Diff line change
Expand Up @@ -43,7 +43,7 @@ def run(self):
link=entry.link,
).save()
except Exception as e:
log.exception('Exception')
log.error('Exception')
impl.log.otherError("newsfeed._newsDaemon", e)

self.sleep(django.conf.settings.NEWSFEED_POLLING_INTERVAL)
2 changes: 1 addition & 1 deletion ezidapp/management/commands/proc-search-indexer.py
Original file line number Diff line number Diff line change
Expand Up @@ -94,7 +94,7 @@ def run(self):
self.log.error(e)
else:
self.log.error('#' * 100)
self.log.exception(f'Exception when handling task "{task_model}"')
self.log.error(f'Exception when handling task "{task_model}"')

task_model.error = str(e)
# if self.is_permanent_error(e):
Expand Down
2 changes: 1 addition & 1 deletion ezidapp/management/commands/proc_base.py
Original file line number Diff line number Diff line change
Expand Up @@ -125,7 +125,7 @@ def run(self):
self.log.error(e)
else:
self.log.error('#' * 100)
self.log.exception(f'Exception when handling task "{task_model}"')
self.log.error(f'Exception when handling task "{task_model}"')

task_model.error = str(e)
# if self.is_permanent_error(e):
Expand Down
37 changes: 37 additions & 0 deletions ezidapp/management/commands/test_logging.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,37 @@
import logging
from django.core.management.base import BaseCommand
import traceback

logger = logging.getLogger(__name__)

class Command(BaseCommand):
help = "Tests exception logging in Django with deeper stack traces"

def simple_error(self, e):
"""Extracts the exception name, HTTP status code (if applicable), filename, and line number."""
tb = traceback.extract_tb(e.__traceback__)[0] # Get last traceback entry
error_msg = f"{type(e).__name__} in {tb.filename} at line {tb.lineno}"

return error_msg

def recursive_function(self, depth=3):
"""Recursively calls itself to create a deeper stack trace"""
if depth == 0:
raise ValueError("Intentional error at max recursion depth!")
return self.recursive_function(depth - 1)

def wrapper_function(self):
"""Wrapper function to add another layer to the stack"""
return self.recursive_function()

def handle(self, *args, **kwargs):
self.stdout.write(self.style.SUCCESS("Running exception logging test..."))

try:
self.wrapper_function() # Indirectly calls the recursive function
except ValueError as e:
logger.error("Caught a ValueError with logger.error")
logger.exception("Caught a ValueError with logger.exception")
logger.error(self.simple_error(e)) # Custom error message

self.stdout.write(self.style.SUCCESS("Logging test completed. Check logs."))
2 changes: 1 addition & 1 deletion ezidapp/models/user.py
Original file line number Diff line number Diff line change
Expand Up @@ -131,7 +131,7 @@ def authenticate(self, password):
password, self.password
)
except Exception as e:
logger.exception('failed')
logger.error('failed')

if not django.contrib.auth.hashers.check_password(password, self.password):
logger.debug('Auth denied. Password check failed')
Expand Down
2 changes: 1 addition & 1 deletion impl/api.py
Original file line number Diff line number Diff line change
Expand Up @@ -137,7 +137,7 @@ def _readInput(request):
return f"error: bad request - ANVL parse error ({str(e)})"
except Exception:
msg_str = "error: bad request - malformed or incomplete request body"
logging.exception(msg_str)
logging.error(msg_str)
return msg_str


Expand Down
2 changes: 1 addition & 1 deletion impl/http_client.py
Original file line number Diff line number Diff line change
Expand Up @@ -76,7 +76,7 @@ def check_url(url: str)->Dict[str, Union[str, int]]:
success = True
log.info("Received complete HTML page when error occurred: " + error)
else:
log.exception(error)
log.error(error)
except Exception as e:
error = "Exception: " + str(e)[:200]

Expand Down
2 changes: 1 addition & 1 deletion impl/log.py
Original file line number Diff line number Diff line change
Expand Up @@ -161,7 +161,7 @@ def badRequest(transactionId):
faulty."""
# _log.info("%s END BADREQUEST" % transactionId.hex)
msg_str = f'{transactionId.hex} END BADREQUEST'
logging.exception(msg_str)
logging.error(msg_str)
_log.info(msg_str)


Expand Down