logging KeyError: '<key>'

If the main logger of the application has "extra" fields on, the error loggings inside urllib3 makes the error "KeyError" to occur. Here is a sample snippet to try:

``` python
import requests
import logging

logger = logging.getLogger()
logStdOut = logging.StreamHandler()
LOGFORMATCNSL=logging.Formatter("%(asctime)s %(message)s %(aVar)s %(bVar)s")
logStdOut.setFormatter(LOGFORMATCNSL)
logStdOut.setLevel(logging.DEBUG)
logger.setLevel(logging.NOTSET)
logger.addHandler(logStdOut)

def tryThis():
    logger.error("deneme", extra={"aVar": "aVal", "bVar": "bVal"})
    conn = requests.get("http://www.google.com")
    conn.close()

tryThis()

```

And I get this result:

```
2014-01-28 23:54:16,270 deneme aVal bVal
Traceback (most recent call last):
  File "/usr/lib/python3.3/logging/__init__.py", line 937, in emit
    msg = self.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 808, in format
    return fmt.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 549, in format
    s = self.formatMessage(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 518, in formatMessage
    return self._style.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 364, in format
    return self._fmt % record.__dict__
KeyError: 'aVar'
Logged from file connectionpool.py, line 172
Traceback (most recent call last):
  File "/usr/lib/python3.3/logging/__init__.py", line 937, in emit
    msg = self.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 808, in format
    return fmt.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 549, in format
    s = self.formatMessage(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 518, in formatMessage
    return self._style.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 364, in format
    return self._fmt % record.__dict__
KeyError: 'aVar'
Logged from file connectionpool.py, line 345
Traceback (most recent call last):
  File "/usr/lib/python3.3/logging/__init__.py", line 937, in emit
    msg = self.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 808, in format
    return fmt.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 549, in format
    s = self.formatMessage(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 518, in formatMessage
    return self._style.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 364, in format
    return self._fmt % record.__dict__
KeyError: 'aVar'
Logged from file connectionpool.py, line 172
Traceback (most recent call last):
  File "/usr/lib/python3.3/logging/__init__.py", line 937, in emit
    msg = self.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 808, in format
    return fmt.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 549, in format
    s = self.formatMessage(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 518, in formatMessage
    return self._style.format(record)
  File "/usr/lib/python3.3/logging/__init__.py", line 364, in format
    return self._fmt % record.__dict__
KeyError: 'aVar'
Logged from file connectionpool.py, line 345
[Finished in 1.6s]
```

However, if we change the formatting line of the test snippet into this, there is no exception like the above:

```
LOGFORMATCNSL=logging.Formatter("%(asctime)s %(message)s")
```

So, does the NullHandler() for the libraries logging make this, or there is sth else going on. Because, a library must not try to log anything into my application logging, without extra effort of mine I guess.

Here is my system info:

```
# uname -a
Linux myhostname 3.8.0-35-generic #50-Ubuntu SMP Tue Dec 3 01:24:59 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

# lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=13.04
DISTRIB_CODENAME=raring
DISTRIB_DESCRIPTION="Ubuntu 13.04"

#  python
Python 3.3.1 (default, Sep 25 2013, 19:29:01) 
[GCC 4.7.3] on linux

# pip3 list
-lxc (0.1)
apturl (0.5.2ubuntu1)
Brlapi (0.5.7)
cchardet (0.3.5)
chardet (2.2.1)
command-not-found (0.3)
defer (1.0.6)
dirspec (4.2.0)
distribute (0.6.34)
friends (0.1)
httplib2 (0.7.7)
jusText (2.0.0)
language-selector (0.1)
louis (2.4.1)
lxml (3.1.0)
nose (1.3.0)
oauthlib (0.3.7)
onboard (0.99.0-alpha1-tr1190)
oneconf (0.3.3)
piston-mini-client (0.7.5)
pycrypto (2.6)
pygobject (3.8.2)
pymongo (2.6.3)
python-apt (0.8.8ubuntu6)
python-debian (0.1.21-nmu2ubuntu1)
pyxdg (0.25)
requests (2.2.1)
six (1.2.0)
software-center-aptd-plugins (0.0.0)
thin-client-config-agent (0.7)
ubuntu-drivers-common (0.0.0)
ufw (0.33-0ubuntu3)
unattended-upgrades (0.1)
unity-scope-gdrive (0.7)
usb-creator (0.2.23)
virtkey (0.63.0)
Werkzeug (0.9.4)
xdiagnose (3.5.1)
xkit (0.0.0)
```


Hi there! Thanks for raising this!

We bring urllib3 in to Requests wholesale without changes, so can I ask you to open this issue over there? That will lead to a fix for Requests _and_ a fix for urllib3. =)


BTW,

``` python
logger.setLevel(logging.ERROR)
```

makes that exceptions disappear, I know. However, this limits my usage as you may understand.


Writing for next commers with same problem... After 3 days with this problem, I just (seconds ago) figured out 

1) First solution would be wrapping the requests.get() mehtod inside a try/except block itself.
2) Would be with this patch for requests library 2.2.1:

``` diff
+++ __init__.py 2014-01-29 00:15:44.000000000 +0200
@@ -74,4 +74,5 @@ except ImportError:
         def emit(self, record):
             pass

-logging.getLogger(__name__).addHandler(NullHandler())
+logger = logging.getLogger(__name__)
+logger.addHandler(NullHandler())
```

and therefore, with small tweak in my own application:

``` python
import requests
import python
requests.logger.setLevel(logging.ERROR)
[...]
```

hope helps anyone.


What is the status on this issue?

Nothing has changed, but as discussed, this is technically a urllib3 bug and needs to be reproduced directly using that library.