From f317800cb707093ffc40cfe919e8b4d1ffe2d001 Mon Sep 17 00:00:00 2001
From: Kevin McCarthy <me@kevinmccarthy.org>
Date: Sun, 27 Apr 2014 11:29:06 -1000
Subject: [PATCH] Add Logging

This helps to figure out which matcher has decided your two cassettes
differ, and figure out when your cassettes have hit the network.

Closes #34
---
 README.md             | 36 +++++++++++++++++++++++++++++++++++-
 vcr/__init__.py       | 12 ++++++++++++
 vcr/matchers.py       | 12 +++++++++++-
 vcr/stubs/__init__.py | 16 +++++++++++++++-
 4 files changed, 73 insertions(+), 3 deletions(-)

diff --git a/README.md b/README.md
index 943ea80..6d30f00 100644
--- a/README.md
+++ b/README.md
@@ -287,10 +287,44 @@ how to set this up.  I have marked the boto tests as optional in Travis so you
 don't have to worry about them failing if you submit a pull request.
 
 
+## Logging
+VCR.py has a few log messages you can turn on to help you figure out if HTTP
+requests are hitting a real server or not.  You can turn them on like this:
+
+```python
+import vcr
+import requests
+import logging
+
+logging.basicConfig() # you need to initialize logging, otherwise you will not see anything from vcrpy
+vcr_log = logging.getLogger("vcr")
+vcr_log.setLevel(logging.INFO)
+
+with vcr.use_cassette('headers.yml'):
+        requests.get('http://httpbin.org/headers')
+```
+
+The first time you run this, you will see:
+
+```
+INFO:vcr.stubs:<Request (GET) http://httpbin.org/headers> not in cassette, sending to real server
+```
+
+The second time, you will see:
+
+```
+INFO:vcr.stubs:Playing response for <Request (GET) http://httpbin.org/headers> from cassette
+```
+
+If you set the loglevel to DEBUG, you will also get information about which
+matchers didn't match. This can help you with debugging custom matchers.
+
+
 ## Changelog
   * 1.0.0 (in development) - Bump supported Python3 version to 3.4, fix some
     bugs with Boto support (thanks @marusich), fix error with URL field
-    capitalization in README (thanks @simon-weber)
+    capitalization in README (thanks @simon-weber), added some log messages
+    to help with debugging.
   * 0.7.0: VCR.py now supports Python 3! (thanks @asundg)  Also I refactored
     the stub connections quite a bit to add support for the putrequest and
     putheader calls.  This version also adds support for httplib2 (thanks
diff --git a/vcr/__init__.py b/vcr/__init__.py
index 742254d..03fdb3b 100644
--- a/vcr/__init__.py
+++ b/vcr/__init__.py
@@ -1,5 +1,17 @@
+import logging
 from .config import VCR
 
+# Set default logging handler to avoid "No handler found" warnings.
+import logging
+try:  # Python 2.7+
+    from logging import NullHandler
+except ImportError:
+    class NullHandler(logging.Handler):
+        def emit(self, record):
+            pass
+
+logging.getLogger(__name__).addHandler(NullHandler())
+
 default_vcr = VCR()
 
 
diff --git a/vcr/matchers.py b/vcr/matchers.py
index 502c0c8..0adf3a8 100644
--- a/vcr/matchers.py
+++ b/vcr/matchers.py
@@ -1,3 +1,6 @@
+import logging
+log = logging.getLogger(__name__)
+
 def method(r1, r2):
     return r1.method == r2.method
 
@@ -22,5 +25,12 @@ def headers(r1, r2):
     return r1.headers == r2.headers
 
 
+def _log_matches(matches):
+    differences = [m for m in matches if not m[0]]
+    if differences:
+        log.debug('Requests differ according to the following matchers: {0}'.format(differences))
+
 def requests_match(r1, r2, matchers):
-    return all(m(r1, r2) for m in matchers)
+    matches = [(m(r1, r2), m) for m in matchers]
+    _log_matches(matches)
+    return all([m[0] for m in matches])
diff --git a/vcr/stubs/__init__.py b/vcr/stubs/__init__.py
index e8e6843..04c0f79 100644
--- a/vcr/stubs/__init__.py
+++ b/vcr/stubs/__init__.py
@@ -4,6 +4,7 @@ try:
     import http.client
 except ImportError:
     pass
+import logging
 import six
 from six.moves.http_client import (
     HTTPConnection,
@@ -16,6 +17,8 @@ from vcr.request import Request
 from vcr.errors import CannotOverwriteExistingCassetteException
 from . import compat
 
+log = logging.getLogger(__name__)
+
 
 class VCRFakeSocket(object):
     """
@@ -118,7 +121,6 @@ class VCRConnection:
 
     def request(self, method, url, body=None, headers=None):
         '''Persist the request metadata in self._vcr_request'''
-
         self._vcr_request = Request(
             protocol=self._protocol,
             host=self.real_connection.host,
@@ -128,6 +130,7 @@ class VCRConnection:
             body=body,
             headers=headers or {}
         )
+        log.debug('Got {0}'.format(self._vcr_request))
 
         # Note: The request may not actually be finished at this point, so
         # I'm not sending the actual request until getresponse().  This
@@ -149,6 +152,7 @@ class VCRConnection:
             body="",
             headers={}
         )
+        log.debug('Got {0}'.format(self._vcr_request))
 
     def putheader(self, header, *values):
         for value in values:
@@ -182,6 +186,11 @@ class VCRConnection:
         if self._vcr_request in self.cassette and \
                 self.cassette.record_mode != "all" and \
                 self.cassette.rewound:
+            log.info(
+                "Playing response for {0} from cassette".format(
+                    self._vcr_request
+                )
+            )
             response = self.cassette.play_response(self._vcr_request)
             return VCRHTTPResponse(response)
         else:
@@ -195,6 +204,11 @@ class VCRConnection:
             # Otherwise, we should send the request, then get the response
             # and return it.
 
+            log.info(
+                "{0} not in cassette, sending to real server".format(
+                    self._vcr_request
+                )
+            )
             self.real_connection.request(
                 method=self._vcr_request.method,
                 url=self._vcr_request.path,