Log request issues

[Vectornaut]

This PR sets up a system to log requests that go wrong. This involves several smaller changes.

Logging

• Switches to structlog for all explicit logging. This makes it easy to write JSON logs that include all the response data from problematic requests, while also writing summary logs to standard output.
  • To keep built-in logs working, I store the structured logger in a new structlogger attribute of the app, leaving the default logger attribute as it is.
  • To do: once the commit hash endpoint is working, would it make sense to log a startup message with the current commit hash every time create_app runs? This might make it easier to see which version of the software other log entries are coming from.
• Adds an oeis_get wrapper for OEIS requests, which automatically logs any problems.

Testing

• Adds a unit test that just writes a log message and checks whether that works.
• Revises the end-to-end lookup error test to comfirm that the failed request is logged as expected.
  • To accomplish this, adds a way to verify log messages in the abstract request test

[katestange]

Maybe this needs some documentation (markdown), like where are logs written to, and whether anything needs to be done to enable logging, and what is logged? Other than that, it runs fine on my system and I've pasted in the flask test output for the unit test, which looks like it was ok. I can verify that it creates api.log on my system if it doesn't exist, although I wasn't sure how to cause it to log something in there (I played with some sequences and nothing was logged although in the shell it showed various successful API calls).

[Vectornaut]

Updates:

• Brought the PR up to date with the new commit hash endpoint code.
• Made each "request issue" log entry include a dump of the request-response conversation, like it's supposed to. (I thought I'd done this already, but I accidentally told the logger to throw away the dump instead of including it.)

[katestange]

Let me know when you want me to test it all again.

[gwhitney]

I just pulled the current version of this PR and ran its tests, and the test of getting a nonexistent sequence failed. So @Vectornaut I am guessing this is not ready for further review and for building on to get a head start on #77? Let us know when you think it's stable enough. Thanks!

[Vectornaut]

I just pulled the current version of this PR and ran its tests, and the test of getting a nonexistent sequence failed

Oh, right—I fixed the bug that was leaving HTTP response dumps out of log entries, but I haven't yet updated the test's expected log entry to include a response dump. The easiest test (comparing against a fixed expected log message) would stop working if the OEIS changes its 404 page. Is that easy test good enough for now?

[gwhitney]

I just pulled the current version of this PR and ran its tests, and the test of getting a nonexistent sequence failed

Oh, right—I fixed the bug that was leaving HTTP response dumps out of log entries, but I haven't yet updated the test's expected log entry to include a response dump. The easiest test (comparing against a fixed expected log message) would stop working if the OEIS changes its 404 page. Is that easy test good enough for now?

I think definitely so. The OEIS tends to move slowly, technologically speaking, and it's easy for us to update test expectations if they do change. Thanks!

[Vectornaut]

Including the HTTP response dump in the nonexistent sequence test was more annoying than I expected, because parts of the response (the date line and the "last updated" ticker on the OEIS 404 page) are time-dependent. However, I've managed to cut them out, yielding a test that covers at least part of the expected 404 response.

[Vectornaut]

I think this is ready to review again! Could you both try it out, review the issues you brought up, and resolve the conversations that have been addressed to your satisfaction?

[gwhitney]

Oops:

backscope> git checkout logbad
Switched to branch 'logbad'
backscope> git pull
[...]
Updating 8893a52..9929fb8
[...]
backscope> sh tools/install-requirements.sh
[...]
Backscope dependencies successfully installed
backscope> flask test
Traceback (most recent call last):
  File "/home/glen/code/backscope/.venv/bin/flask", line 8, in <module>
    sys.exit(main())
             ^^^^^^
  File "/home/glen/code/backscope/.venv/lib64/python3.11/site-packages/flask/cli.py", line 1064, in main
    cli.main()
  File "/home/glen/code/backscope/.venv/lib64/python3.11/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
         ^^^^^^^^^^^^^^^^
  File "/home/glen/code/backscope/.venv/lib64/python3.11/site-packages/click/core.py", line 1682, in invoke
    cmd_name, cmd, args = self.resolve_command(ctx, args)
                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/glen/code/backscope/.venv/lib64/python3.11/site-packages/click/core.py", line 1729, in resolve_command
    cmd = self.get_command(ctx, cmd_name)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/glen/code/backscope/.venv/lib64/python3.11/site-packages/flask/cli.py", line 579, in get_command
    app = info.load_app()
          ^^^^^^^^^^^^^^^
  File "/home/glen/code/backscope/.venv/lib64/python3.11/site-packages/flask/cli.py", line 313, in load_app
    app = locate_app(import_name, None, raise_if_not_found=False)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/glen/code/backscope/.venv/lib64/python3.11/site-packages/flask/cli.py", line 219, in locate_app
    __import__(module_name)
  File "/home/glen/code/backscope/wsgi.py", line 5, in <module>
    app = create_app()
          ^^^^^^^^^^^^
  File "/home/glen/code/backscope/flaskr/__init__.py", line 129, in create_app
    file_handler = create_file_handler()
                   ^^^^^^^^^^^^^^^^^^^^^
  File "/home/glen/code/backscope/flaskr/__init__.py", line 57, in create_file_handler
    handler = RotatingFileHandler('logs/api.log', maxBytes=2*10**7, backupCount=9)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.11/logging/handlers.py", line 155, in __init__
    BaseRotatingHandler.__init__(self, filename, mode, encoding=encoding,
  File "/usr/lib64/python3.11/logging/handlers.py", line 58, in __init__
    logging.FileHandler.__init__(self, filename, mode=mode,
  File "/usr/lib64/python3.11/logging/__init__.py", line 1181, in __init__
    StreamHandler.__init__(self, self._open())
                                 ^^^^^^^^^^^^
  File "/usr/lib64/python3.11/logging/__init__.py", line 1213, in _open
    return open_func(self.baseFilename, self.mode,
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
FileNotFoundError: [Errno 2] No such file or directory: '/home/glen/code/backscope/logs/api.log'

Does it fail if you have no logs directory and/or no pre-existing api.log file? Needs to be resilient to those possibilities, if so.
Thanks for looking into this!

[katestange]

It's possible you forgot to add all the files/directories needed? Did you move logs into a subdirectory? When I do flask run I get

FileNotFoundError: [Errno 2] No such file or directory: '/home/katestange/data/projects/numberscope/frontscope-backscope/backscope/logs/api.log'

and indeed, I have no directory "logs". flask test seems to have a similar problem

[gwhitney]

Took the liberty of adding where to find the log files in production, since it seems on-point for this PR and then will also close #55.

[gwhitney]

And since this now touches server-administration.md, removed warning about get_commit not working to kill #115 too.

[Vectornaut]

Took the liberty of adding where to find the log files in production

Awesome. I'm almost done with the revised commit message.

[Vectornaut]

Here's my proposed commit message! Let me know if I should shorten it (or feel free to revise it unilaterally). While writing it, I realized that the current_app.structlogger attribute should be documented in the documentation, not just in the PR. I made an extra commit to do that.

Log request issues

Set up a system to log requests that go wrong. This involves several
smaller changes.

--- Logging ---

Switch to the `structlog` package for all explicit logging. This makes
it easy to write JSON logs that include all the response data from
problematic requests, while also writing summary logs to standard
output.

Add an `oeis_get` wrapper for OEIS requests, which automatically logs
any problems.

Move logs to a new `logs` folder, which is always present because it
contains a tracked `.gitignore` file. Tell Git to ignore log files, to
guard against accidentally checking them into the repository.

--- Testing ---

Add a unit test which just writes a log message.

Revise the end-to-end lookup error test to comfirm that the failed
request is logged as expected. To accomplish this, add facilities for
checking log messages in the abstract endpoint test. These are described
in the comments of `abstract_endpoint_test.py`.

[gwhitney]

My apologies, I saw the odd merge of logbad into logbad in the git log and didn't know what that was all about, so did a "git diff" versus main just to be sure all was well, and all these "noise" items came up which it would be good to squelch here before the merge. Sorry.

[Vectornaut]

My apologies, I saw the odd merge of logbad into logbad in the git log and didn't know what that was all about

No, it's a good idea to clean these up. Because I'd imagined dealing with formatting errors in a separate commit, I didn't think to make sure this PR didn't introduce new formatting errors. I should be able to finish that in a few minutes.

[Vectornaut]

Commit aa5db13 should prevent this PR from introducing new formatting inconsistencies. You may want to review the alphabetization of imports: I tried to imitate existing files, but I'm not sure I did it correctly.