add exc_info to access_logger #3557

samuelcolvin · 2019-01-20T17:38:27Z

What do these changes do?

~~Add exc_info argument to AccessLogger.log.~~

call AccessLogger.log with the current exception available from sys.exc_info().

I'm trying to implement a custom AccessLogger to both print useful information to the terminal during development and log information about failed requests to sentry or equivalent in production.

The problem is that aiohttp.server log methods are only called on an exception and without the request and response objects, while AccessLogger.log is called on every request but without any information about the exception.

Currently, to achieve what I want I would have to either

print/post two log messages, one with details on the request, one with the exception. That would ok in the terminal but be very ugly in sentry or equivilant.
use middleware which I guess it what most people do, but means ignoring AccessLogger completely and modifying the app. This is particularly problematic in aiohttp-devtools which is one of the places I want to use this.

Are there changes in behavior for the user?

Only if they've implemented a custom AccessLogger

Checklist

I think the code is well written
Unit tests for the changes exist
Documentation reflects the changes
Add a new news fragment into the CHANGES folder
- name it <issue_id>.<type> for example (588.bugfix)
- if you don't have an issue_id change it to the pr id after creating the pr
- ensure type is one of the following:
  - .feature: Signifying a new feature.
  - .bugfix: Signifying a bug fix.
  - .doc: Signifying a documentation improvement.
  - .removal: Signifying a deprecation or removal of public API.
  - .misc: A ticket has been closed, but it is not of interest to users.
- Make sure to use full sentences with correct case and punctuation, for example: "Fix issue with non-ascii contents in doctest text files."

codecov-io · 2019-01-20T19:47:43Z

Codecov Report

Merging #3557 into master will increase coverage by 0.07%.
The diff coverage is 100%.

@@            Coverage Diff             @@
##           master    #3557      +/-   ##
==========================================
+ Coverage   97.87%   97.94%   +0.07%     
==========================================
  Files          43       43              
  Lines        8561     8576      +15     
  Branches     1374     1374              
==========================================
+ Hits         8379     8400      +21     
+ Misses         77       74       -3     
+ Partials      105      102       -3

Impacted Files	Coverage Δ
aiohttp/web_protocol.py	`93.24% <100%> (+0.48%)`	⬆️
aiohttp/cookiejar.py	`100% <0%> (ø)`	⬆️
aiohttp/test_utils.py	`99.68% <0%> (ø)`	⬆️
aiohttp/multipart.py	`97.03% <0%> (+0.89%)`	⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update c8cbbcc...7da7d2a. Read the comment docs.

asvetlov · 2019-01-21T15:43:04Z

@samuelcolvin would you fix mypy check?

samuelcolvin · 2019-01-21T15:43:45Z

of course, I just wanted to check you think this is a good idea before I do more work on it?

asvetlov · 2019-01-21T22:58:59Z

Honestly, I don't know.
It changes our public API and breaks existing access loggers.
On other hand the logger can ask for sys.exc_info() internally if needed.
Is the exception context cleared by aiohttp protocol itself?

samuelcolvin · 2019-01-21T23:37:54Z

It's not cleared explicitly, but I tried sys.exc_info() and it didn't work, I'll check again and confirm.

The option is to add exc_info to the response so it doesn't break existing functionality but is still available?

asvetlov · 2019-01-22T00:23:33Z

Do you propose to add response.exc_info attribute?
It sounds a weird a little.
We can invent a different abstract logger class to accept exception info -- or change the existing code to always have an exception context when the logger is called.

Addition exc_info to logging python module was done in a backward compatible way.
It would be nice to keep the compatibility in this aspect for aiohttp if possible

samuelcolvin · 2019-01-22T12:54:42Z

Ok, I'll try that.

samuelcolvin · 2019-01-23T12:53:39Z

Ok, all changed, but I'm not sure why tests are failing, seems to be something to do with cython.

samuelcolvin · 2019-01-30T11:57:56Z

@asvetlov I think this is basically done.

However I have another question/feature request:

How would you feel about access_logger.log being a coroutine? In my use case (detailed error reporting), there is a reasonable chance that the log method will need to make async calls. Eg. to populate the user field of sentry an app might want to access the database to get the user's name from the user's ID which might be in the session, or the error details might want access to the request body even if it hasn't already been read.

I know this is currently possible with middleware, but I think using AccessLogger would be more elegant as it avoid modifying the app, so can be completely handled but an "app runner".

This could be done in a backwards compatible way by adding a alog method which by default just calls log or by inspecting log to see if it's a coroutine.

asvetlov · 2019-05-10T17:22:25Z

@samuelcolvin would you fix merge conflicts?
I review the PR just after getting it done

samuelcolvin · 2019-05-10T17:23:07Z

will do

cla-bot · 2019-05-10T17:39:42Z

Thank you for your pull request and welcome to our community. We require contributors to sign our Contributor License Agreement, and we don"t seem to have the users @samuelcolvin on file. In order for us to review and merge your code, please contact the project maintainers to get yourself added.

samuelcolvin · 2019-05-10T17:42:27Z

Hopefully conflicts are fixed. How do I sign the contributor agreement?

asvetlov · 2019-05-10T18:19:50Z

Just ignore CLA for now.
The bot has no proper setup still, sorry.

samuelcolvin · 2019-05-11T15:50:29Z

ok no problem, passing except for CLA.

asvetlov · 2019-05-12T14:22:36Z

aiohttp/web_protocol.py

@@ -342,9 +342,11 @@ def force_close(self) -> None:
    def log_access(self,
                   request: BaseRequest,
                   response: StreamResponse,
-                   time: float) -> None:
+                   request_start: Optional[float]) -> None:


Looks like reverting back request_start to strict float simplifies a code.

aiohttp/web_protocol.py

asvetlov

lgtm

samuelcolvin · 2019-05-12T19:43:17Z

@asvetlov I think this is basically done.

However I have another question/feature request:

How would you feel about access_logger.log being a coroutine? In my use case (detailed error reporting), there is a reasonable chance that the log method will need to make async calls. Eg. to populate the user field of sentry an app might want to access the database to get the user's name from the user's ID which might be in the session, or the error details might want access to the request body even if it hasn't already been read.

I know this is currently possible with middleware, but I think using AccessLogger would be more elegant as it avoid modifying the app, so can be completely handled but an "app runner".

This could be done in a backwards compatible way by adding a alog method which by default just calls log or by inspecting log to see if it's a coroutine.

@asvetlov did you see this question?

asvetlov · 2019-05-12T19:52:12Z

Async log method makes sense maybe. I have no objections and have no strong +1 feeling.
It should be done in a backward compatible way, sure.
It requires a separate PR IMHO.

BTW do you inherit your logger from AccessLogger or AbstractAccessLogger?

asvetlov · 2019-05-12T19:52:41Z

The tests failure is not related to PR but a result of #3520

samuelcolvin · 2019-05-12T19:54:53Z

AbstractAccessLogger, see here but mostly I'm not using access logger's at all because of exception context and the need for a coroutine.

asvetlov · 2019-05-12T21:03:11Z

After thinking about the idea of .alog() it confuses me.
There is better (I hope) proposal:

Introduce a new AbstractAsyncAccessLogger class with the only async def log(...) method -- like AbstractAccessLogger.log but async function.
Provide adaptor class that implements AbstractAsyncAccessLogger interface and accepts synchronous AbstractAccessLogger instance in its constructor.
On RequestHandler initialization do check of the logger. If it is an instance of AbstractAccessLoger -- wrap it with adaptor. If the logger is an instance if AbstractAsyncAccessLogger -- pass it as is, raise an error otherwise.

What do you think?

samuelcolvin · 2019-05-13T09:20:59Z

Agreed, I think 3 will be the easiest appraoch. Will do in another PR

asvetlov · 2019-05-13T09:24:31Z

Bump to rebuild CI

asvetlov · 2019-05-13T09:25:13Z

I thought that my proposal has all three bullets necessary, not only the last one :)

asvetlov · 2019-05-13T09:25:43Z

Let's merge the PR on green

asvetlov · 2019-05-13T13:52:03Z

Done!
Thanks, @samuelcolvin !

kxepal · 2019-05-13T13:52:55Z

:slowpoke:,but 👍 for async log. This will help a lot in future.

samuelcolvin · 2019-05-13T13:58:57Z

working on it in #3767

samuelcolvin requested a review from asvetlov as a code owner January 20, 2019 17:38

samuelcolvin requested a review from webknjaz as a code owner January 23, 2019 12:01

samuelcolvin added 6 commits January 29, 2019 11:21

add exc_info to access_logger

cdf57d3

fix ExcInfo type

329c543

fix tests

45d2c84

rewrite to maintain exception context

ec1d2df

fix tests and mypy

493970a

add changes and docs

0343eaa

Merge branch 'master' into access-loger-exc_info

690cf60

asvetlov reviewed May 12, 2019

View reviewed changes

unconditional loop.time()

7da7d2a

asvetlov approved these changes May 12, 2019

View reviewed changes

asvetlov closed this May 13, 2019

asvetlov reopened this May 13, 2019

asvetlov merged commit 78a2fec into aio-libs:master May 13, 2019

samuelcolvin deleted the access-loger-exc_info branch May 13, 2019 13:56

samuelcolvin mentioned this pull request May 13, 2019

implementing AbstractAsyncAccessLogger #3767

Merged

5 tasks

samuelcolvin mentioned this pull request Aug 21, 2019

AIOHTTP: Attach request body getsentry/sentry-python#220

Closed

lock bot added the outdated label May 20, 2020

psf-chronographer bot added the bot:chronographer:provided There is a change note present in this PR label May 20, 2020

lock bot locked as resolved and limited conversation to collaborators May 20, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

add exc_info to access_logger #3557

add exc_info to access_logger #3557

samuelcolvin commented Jan 20, 2019 •

edited

Loading

codecov-io commented Jan 20, 2019 •

edited

Loading

asvetlov commented Jan 21, 2019

samuelcolvin commented Jan 21, 2019 •

edited

Loading

asvetlov commented Jan 21, 2019

samuelcolvin commented Jan 21, 2019 •

edited by asvetlov

Loading

asvetlov commented Jan 22, 2019 •

edited

Loading

samuelcolvin commented Jan 22, 2019

samuelcolvin commented Jan 23, 2019

samuelcolvin commented Jan 30, 2019

asvetlov commented May 10, 2019

samuelcolvin commented May 10, 2019

cla-bot bot commented May 10, 2019

samuelcolvin commented May 10, 2019

asvetlov commented May 10, 2019

samuelcolvin commented May 11, 2019

asvetlov May 12, 2019

asvetlov left a comment

samuelcolvin commented May 12, 2019

asvetlov commented May 12, 2019

asvetlov commented May 12, 2019

samuelcolvin commented May 12, 2019 •

edited

Loading

asvetlov commented May 12, 2019

samuelcolvin commented May 13, 2019

asvetlov commented May 13, 2019

asvetlov commented May 13, 2019

asvetlov commented May 13, 2019

asvetlov commented May 13, 2019

kxepal commented May 13, 2019

samuelcolvin commented May 13, 2019

add exc_info to access_logger #3557

add exc_info to access_logger #3557

Conversation

samuelcolvin commented Jan 20, 2019 • edited Loading

What do these changes do?

Are there changes in behavior for the user?

Checklist

codecov-io commented Jan 20, 2019 • edited Loading

Codecov Report

asvetlov commented Jan 21, 2019

samuelcolvin commented Jan 21, 2019 • edited Loading

asvetlov commented Jan 21, 2019

samuelcolvin commented Jan 21, 2019 • edited by asvetlov Loading

asvetlov commented Jan 22, 2019 • edited Loading

samuelcolvin commented Jan 22, 2019

samuelcolvin commented Jan 23, 2019

samuelcolvin commented Jan 30, 2019

asvetlov commented May 10, 2019

samuelcolvin commented May 10, 2019

cla-bot bot commented May 10, 2019

samuelcolvin commented May 10, 2019

asvetlov commented May 10, 2019

samuelcolvin commented May 11, 2019

asvetlov May 12, 2019

Choose a reason for hiding this comment

asvetlov left a comment

Choose a reason for hiding this comment

samuelcolvin commented May 12, 2019

asvetlov commented May 12, 2019

asvetlov commented May 12, 2019

samuelcolvin commented May 12, 2019 • edited Loading

asvetlov commented May 12, 2019

samuelcolvin commented May 13, 2019

asvetlov commented May 13, 2019

asvetlov commented May 13, 2019

asvetlov commented May 13, 2019

asvetlov commented May 13, 2019

kxepal commented May 13, 2019

samuelcolvin commented May 13, 2019

samuelcolvin commented Jan 20, 2019 •

edited

Loading

codecov-io commented Jan 20, 2019 •

edited

Loading

samuelcolvin commented Jan 21, 2019 •

edited

Loading

samuelcolvin commented Jan 21, 2019 •

edited by asvetlov

Loading

asvetlov commented Jan 22, 2019 •

edited

Loading

samuelcolvin commented May 12, 2019 •

edited

Loading