Log data fetched from URLs to make debugging easier (at trace log level).#1589
Log data fetched from URLs to make debugging easier (at trace log level).#1589liiight merged 7 commits intoFlexget:developfrom tobinjt:develop
Conversation
To make debugging easier, log contents of fetched URLs at trace level. Browsers process Javascript, handle iframes, and more that flexget doesn't; seeing the actual data processed by flexget rather than looking at the URL in your browser makes it easier to figure out why you're not getting any results.
liiight
left a comment
There was a problem hiding this comment.
I'm not even sure what data will be added here and what benefit this has.
flexget/utils/requests.py
Outdated
| log.debug('Fetching URL %s with args %s and kwargs %s', url, args, kwargs) | ||
| result = super(Session, self).request(method, url, *args, **kwargs) | ||
| try: | ||
| log.trace('Contents for URL %s start on next line', url) |
There was a problem hiding this comment.
Creating a log entry that says that there's more log in another line is just silly.
There was a problem hiding this comment.
Collapsed to one line.
flexget/utils/requests.py
Outdated
| result = super(Session, self).request(method, url, *args, **kwargs) | ||
| try: | ||
| log.trace('Contents for URL %s start on next line', url) | ||
| log.trace('%s', result.text) |
There was a problem hiding this comment.
The safe way to do this is test if result even has text:
if hasattr(result, 'text'):
...There was a problem hiding this comment.
requests/models:Request defines the text property, so this will always be available.
flexget/utils/requests.py
Outdated
| try: | ||
| log.trace('Contents for URL %s start on next line', url) | ||
| log.trace('%s', result.text) | ||
| except UnicodeDecodeError: |
There was a problem hiding this comment.
There is no reason to catch a unicode error here, stuff like that should be handled (and are handled) in larger scale.
There was a problem hiding this comment.
There are two problems if this error isn't caught here, and I've added a comment to the code describing them.
- The call stack unwinds until the error is caught, so turning up the log level causes a change in behaviour, which is bad.
- This stack trace is dumped to stderr:
Traceback (most recent call last):
File "/usr/local/Cellar/python/2.7.13/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/handlers.py", line 76, in emit
if self.shouldRollover(record):
File "/usr/local/Cellar/python/2.7.13/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
msg = "%s\n" % self.format(record)
File "/usr/local/Cellar/python/2.7.13/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/init.py", line 734, in format
return fmt.format(record)
File "/Users/johntobin/src/upstream-flexget/flexget/logger.py", line 142, in format
return logging.Formatter.format(self, record)
File "/usr/local/Cellar/python/2.7.13/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/init.py", line 465, in format
record.message = record.getMessage()
File "/usr/local/Cellar/python/2.7.13/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/init.py", line 329, in getMessage
msg = msg % self.args
UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 9604: ordinal not in range(128)
There was a problem hiding this comment.
I under that this raises exception without the except but we have an entirely different issue that deals with this problem.
There was a problem hiding this comment.
I don't understand your comment :( Would you prefer that I remove the exception handling?
There was a problem hiding this comment.
@gazpachoking Thanks, that cleared it up, and I've removed the exception handling.
|
Here's a sample of what's logged: |
|
OK and what does that data provide you with? What problem is this solving? |
|
I can log the exact data that Flexget processed when I'm trying to debug why my config isn't working. E.g. with extratorrent.cc they started returning a block of encoded Javascript rather than HTML; my browser shows me useful results but Flexget doesn't get anything useful out of the page. |
#1558 will systemically handle this problem.
flexget/utils/requests.py
Outdated
| try: | ||
| log.trace('Contents for URL %s start on next line', url) | ||
| log.trace('%s', result.text) | ||
| except UnicodeDecodeError: |
Motivation for changes:
Make it easier to debug Flexget not getting useful results from a URL.
Detailed changes:
To make debugging easier, log contents of fetched URLs at trace level.
Browsers process Javascript, handle iframes, and more that flexget
doesn't; seeing the actual data processed by flexget rather than looking
at the URL in your browser makes it easier to figure out why you're not
getting any results.
Addressed issues:
Config usage if relevant (new plugin or updated schema):
Log and/or tests output (preferably both):
The test failures appear to be completely unrelated to my change.