pytest-dev / pytest-dev/pytest

Caplog don't capture all logs

Open
#7,335 10 comments 2 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

plugin: logging
Dominant language
Python
Stars
14.5k
Forks
3.4k
Avg merge
2d 9h
Merged PRs (30d)
35

Description

Caplog start capturing, but in a specific place capturing is stopped.
It reproduces in one test and does not reproduce in the rest.
Additional I need caplog.set_level('DEBUG') for this test (specify the logging level for caplog, otherwise nothing gets into it at all). In another tests this not need.

Example of output:

root@b1ad842cef21:/usr/src/app# pytest ./tests/functional/test_scraping_wix_site.py -s
/usr/local/lib/python3.7/site-packages/twisted/internet/address.py:101: DeprecationWarning: The usage of `cmp` is deprecated and will be removed on or after 2021-06-01.  Please use `eq` and `order` instead.
  @attr.s(hash=False, repr=False, cmp=False)
====================================================================== test session starts ======================================================================
platform linux -- Python 3.7.3, pytest-5.3.5, py-1.8.1, pluggy-0.13.1
rootdir: /usr/src/app, inifile: pytest.ini
plugins: twisted-1.12, cov-2.8.1
collected 1 item                                                                                                                                                

tests/functional/test_scraping_wix_site.py ---- init logging
2020-06-08 04:43:55,519 - botocore.hooks - DEBUG - Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
2020-06-08 04:43:55,526 - botocore.hooks - DEBUG - Changing event name from before-call.apigateway to before-call.api-gateway

<... some logs ...>

2020-06-08 04:43:55,740 - scrapy.middleware - INFO - Enabled item pipelines:
['crawler.pipelines.MysqlPipeline', 'crawler.pipelines.ScreenshotPipeline']
2020-06-08 04:43:55,740 - scrapy.core.engine - INFO - Spider opened
2020-06-08 04:43:55,760 - scrapy.extensions.logstats - INFO - Crawled 0 pages (at 0 pages/min), scraped 0 items (at 0 items/min)
2020-06-08 04:43:56,447 - urllib3.connectionpool - DEBUG - Starting new HTTP connection (1): splash:8050
2020-06-08 04:43:56,640 - urllib3.connectionpool - DEBUG - http://splash:8050 "POST /_gc HTTP/1.1" 200 72
2020-06-08 04:43:56,666 - urllib3.connectionpool - DEBUG - Starting new HTTP connection (1): splash:8050

<... some logs ...>

2020-06-08 04:44:28,617 - scrapy.statscollectors - INFO - Dumping Scrapy stats:
{'crawler_error_code': 5,
 'downloader/request_bytes': 4233,
 'downloader/request_count': 6,
 'downloader/request_method_count/POST': 6,
 'downloader/response_bytes': 1219766,
 'downloader/response_count': 6,
 'downloader/response_status_count/200': 6,
 'elapsed_time_seconds': 32.852748,
 'finish_reason': 'expected_crawler_error',
 'finish_time': datetime.datetime(2020, 6, 8, 4, 44, 28, 614023),
 'item_scraped_count': 4,
 'log_count/INFO': 4,
 'memusage/max': 148881408,
 'memusage/startup': 148881408,
 'parse_start_url': 'https://www.webseowriter.net',
 'pipeline_mysql/external_links_saved': 0,
 'pipeline_mysql/images_saved': 0,
 'pipeline_mysql/pages_saved': 1,
 'pipeline_mysql/url_links_saved': 0,
 'pipeline_screenshot/screenshots_failure': 0,
 'request_depth_count/0': 1,
 'request_depth_count/1': 1,
 'request_depth_max': 1,
 'response_received_count': 3,
 'robotstxt/request_count': 1,
 'robotstxt/response_count': 1,
 'robotstxt/response_status_count/200': 1,
 'scheduler/dequeued': 6,
 'scheduler/dequeued/memory': 6,
 'scheduler/enqueued': 6,
 'scheduler/enqueued/memory': 6,
 'splash/render.html/request_count': 3,
 'splash/render.html/response_count/200': 3,
 'splash/render.png/request_count': 3,
 'splash/render.png/response_count/200': 3,
 'start_time': datetime.datetime(2020, 6, 8, 4, 43, 55, 761275)}
2020-06-08 04:44:28,618 - scrapy.core.engine - INFO - Spider closed (expected_crawler_error)

F

=========================================================================== FAILURES ============================================================================

In caplog.text:

INFO     scrapy.crawler:crawler.py:49 Overridden settings: {'AJAXCRAWL_ENABLED': True, 'BOT_NAME': 'crawler', 'CONCURRENT_ITEMS': 500, 'CONCURRENT_REQUESTS': 100, 'CONCURRENT_REQUESTS_PER_DOMAIN': 500, 'COOKIES_ENABLED': False, 'DEPTH_LIMIT': 20, 'DEPTH_PRIORITY': 1, 'DEPTH_STATS_VERBOSE': True, 'DOWNLOAD_DELAY': 0.1, 'DOWNLOAD_MAXSIZE': 2097152, 'DOWNLOAD_TIMEOUT': 50, 'FILES_STORE_S3_ACL': 'public-read', 'HTTPCACHE_POLICY': 'scrapy.extensions.httpcache.RFC2616Policy', 'HTTPCACHE_STORAGE': 'scrapy.extensions.httpcache.DbmCacheStorage', 'NEWSPIDER_MODULE': 'crawler.spiders', 'REACTOR_THREADPOOL_MAXSIZE': 50, 'REDIRECT_MAX_TIMES': 10, 'RETRY_ENABLED': False, 'ROBOTSTXT_OBEY': True, 'SPIDER_MODULES': ['crawler.spiders'], 'TELNETCONSOLE_ENABLED': False, 'USER_AGENT': 'Mozilla/5.0 (Windows NT 10.0 Win64x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.77 Safari/537.36'}
INFO     scrapy.middleware:middleware.py:48 Enabled extensions:
['scrapy.extensions.memusage.MemoryUsage',
 'scrapy.extensions.logstats.LogStats',
 'scrapy.extensions.corestats.CoreStats',
 'crawler.extentions.SpiderDetectJS']
INFO     scrapy.middleware:middleware.py:48 Enabled downloader middlewares:
['scrapy.spidermiddlewares.depth.DepthMiddleware',
 'scrapy.downloadermiddlewares.httpauth.HttpAuthMiddleware',
 'scrapy.downloadermiddlewares.downloadtimeout.DownloadTimeoutMiddleware',
 'scrapy.downloadermiddlewares.defaultheaders.DefaultHeadersMiddleware',
 'scrapy.downloadermiddlewares.useragent.UserAgentMiddleware',
 'scrapy.downloadermiddlewares.ajaxcrawl.AjaxCrawlMiddleware',
 'scrapy.downloadermiddlewares.redirect.MetaRefreshMiddleware',
 'crawler.middlewares.CrawlerDownloaderWixMiddleware',
 'rotating_proxies.middlewares.BanDetectionMiddleware',
 'crawler.middlewares.CrawlerDownloaderMiddleware',
 'scrapy_splash.SplashCookiesMiddleware',
 'scrapy_splash.SplashMiddleware',
 'scrapy.downloadermiddlewares.httpproxy.HttpProxyMiddleware',
 'scrapy.downloadermiddlewares.httpcompression.HttpCompressionMiddleware',
 'scrapy.downloadermiddlewares.stats.DownloaderStats']
INFO     scrapy.middleware:middleware.py:48 Enabled spider middlewares:
['scrapy.spidermiddlewares.httperror.HttpErrorMiddleware',
 'scrapy_splash.SplashDeduplicateArgsMiddleware',
 'scrapy.spidermiddlewares.offsite.OffsiteMiddleware',
 'crawler.middlewares.CrawlerSpiderMiddleware',
 'scrapy.spidermiddlewares.referer.RefererMiddleware',
 'scrapy.spidermiddlewares.urllength.UrlLengthMiddleware',
 'scrapy.spidermiddlewares.depth.DepthMiddleware']

Additional Info

root@b1ad842cef21:/usr/src/app# pip list
Package                 Version   
----------------------- ----------
attrs                   19.3.0    
Automat                 20.2.0    
beautifulsoup4          4.8.2     
boto3                   1.12.4    
botocore                1.15.49   
certifi                 2020.4.5.1
cffi                    1.14.0    
chardet                 3.0.4     
click                   7.1.2     
click-log               0.3.2     
constantly              15.1.0    
coverage                5.1       
cryptography            2.9.2     
cssselect               1.1.0     
decorator               4.4.2     
detectem                0.7.1     
docker                  4.1.0     
docutils                0.15.2    
greenlet                0.4.15    
hyperlink               19.0.0    
idna                    2.8       
importlib-metadata      1.6.0     
incremental             17.5.0    
jmespath                0.10.0    
logstash-formatter      0.5.17    
lxml                    4.5.1     
more-itertools          8.3.0     
mysqlclient             1.4.6     
packaging               20.4      
pact-python             0.21.0    
parsel                  1.6.0     
pip                     19.1.1    
pluggy                  0.13.1    
Protego                 0.1.16    
psutil                  5.7.0     
py                      1.8.1     
pyasn1                  0.4.8     
pyasn1-modules          0.2.8     
pycparser               2.20      
PyDispatcher            2.0.5     
PyHamcrest              2.0.2     
pyOpenSSL               19.1.0    
pyparsing               2.4.7     
pytest                  5.3.5     
pytest-cov              2.8.1     
pytest-twisted          1.12      
python-dateutil         2.8.1     
python3-logstash        0.4.80    
queuelib                1.5.0     
requests                2.22.0    
requests-file           1.5.1     
responses               0.10.9    
s3transfer              0.3.3     
scrapoxy                1.11      
Scrapy                  1.8.0     
scrapy-rotating-proxies 0.6.2     
scrapy-splash           0.7.2     
service-identity        18.1.0    
setuptools              41.0.1    
simplejson              3.17.0    
six                     1.15.0    
soupsieve               2.0.1     
SQLAlchemy              1.3.13    
tldextract              2.2.2     
Twisted                 19.10.0   
typing                  3.7.4.1   
urllib3                 1.25.9    
w3lib                   1.21.0    
wcwidth                 0.1.9     
websocket-client        0.57.0    
wheel                   0.33.1    
zipp                    3.1.0     
zope.interface          5.1.0     
WARNING: You are using pip version 19.1.1, however version 20.1.1 is available.
You should consider upgrading via the 'pip install --upgrade pip' command.
root@b1ad842cef21:/usr/src/app# pytest --version
This is pytest version 5.3.5, imported from /usr/local/lib/python3.7/site-packages/pytest/__init__.py
setuptools registered plugins:
  pytest-twisted-1.12 at /usr/local/lib/python3.7/site-packages/pytest_twisted.py
  pytest-cov-2.8.1 at /usr/local/lib/python3.7/site-packages/pytest_cov/plugin.py
root@b1ad842cef21:/usr/src/app# uname -a
Linux b1ad842cef21 5.3.0-46-generic #38~18.04.1-Ubuntu SMP Tue Mar 31 04:17:56 UTC 2020 x86_64 GNU/Linux

Reproduce

I will try to prepare the minimum code a bit later

  • a detailed description of the bug or suggestion
  • output of pip list from the virtual environment you are using
  • pytest and operating system versions
  • minimal example if possible

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by running pytest ./tests/functional/test_scraping_wix_site.py -s and inspect the caplog usage in that test, including caplog.set_level('DEBUG'). Compare the terminal output with caplog.text to identify where capture stops. Done means a minimal reproduction is available and the missing logs are captured consistently with a regression test.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
testing-qa
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.