OrderedDict.popitem()/__str__() raises KeyError

[xZise]

BPO	24667
Nosy	@rhettinger, @larryhastings, @markshannon, @ericsnowcurrently, @1st1, @sigmavirus24, @Lukasa, @xZise, @jayvdb
Files	test.py logging_odict.py: diagnostics helper odict.log: diagnostic output odict_reproduce.py: derived (but independent) reproducer odict_reproduce.py: same reproducer with less clutter odict-correct-resize.diff: patch against master

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/ericsnowcurrently'
closed_at = <Date 2015-08-07.23:51:02.521>
created_at = <Date 2015-07-19.10:40:38.245>
labels = ['type-bug', 'library', 'release-blocker']
title = 'OrderedDict.popitem()/__str__() raises KeyError'
updated_at = <Date 2015-08-09.19:58:37.904>
user = 'https://github.com/xZise'

bugs.python.org fields:

activity = <Date 2015-08-09.19:58:37.904>
actor = 'eric.snow'
assignee = 'eric.snow'
closed = True
closed_date = <Date 2015-08-07.23:51:02.521>
closer = 'eric.snow'
components = ['Library (Lib)']
creation = <Date 2015-07-19.10:40:38.245>
creator = 'xZise'
dependencies = []
files = ['40019', '40068', '40069', '40072', '40078', '40127']
hgrepos = []
issue_num = 24667
keywords = ['patch']
message_count = 41.0
messages = ['246937', '246944', '247011', '247012', '247017', '247029', '247039', '247055', '247057', '247074', '247075', '247104', '247112', '247151', '247351', '247355', '247357', '247390', '247391', '247396', '247417', '247542', '247647', '247674', '247682', '247716', '247718', '247732', '247780', '247960', '248006', '248063', '248094', '248095', '248140', '248147', '248236', '248237', '248288', '248316', '248334']
nosy_count = 10.0
nosy_names = ['rhettinger', 'larry', 'Mark.Shannon', 'python-dev', 'eric.snow', 'yselivanov', 'icordasc', 'Lukasa', 'xZise', 'jayvdb']
pr_nums = []
priority = 'release blocker'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue24667'
versions = ['Python 3.5', 'Python 3.6']

[xZise]

While testing pywikibot using requests and urllib3 on Python 3.6 we got an interesting error:

======================================================================
ERROR: testQueryApiGetter (tests.wikidataquery_tests.TestApiSlowFunctions)
Test that we can actually retreive data and that caching works.
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/travis/build/xZise/pywikibot-core/tests/wikidataquery_tests.py", line 252, in testQueryApiGetter
    data = w.query(q)
  File "/home/travis/build/xZise/pywikibot-core/pywikibot/data/wikidataquery.py", line 601, in query
    data = self.getDataFromHost(fullQueryString)
  File "/home/travis/build/xZise/pywikibot-core/pywikibot/data/wikidataquery.py", line 563, in getDataFromHost
    resp = http.fetch(url)
  File "/home/travis/build/xZise/pywikibot-core/pywikibot/comms/http.py", line 359, in fetch
    error_handling_callback(request)
  File "/home/travis/build/xZise/pywikibot-core/pywikibot/comms/http.py", line 276, in error_handling_callback
    raise request.data
  File "/home/travis/build/xZise/pywikibot-core/pywikibot/comms/http.py", line 255, in _http_process
    auth=auth, timeout=timeout, verify=True)
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/requests/sessions.py", line 465, in request
    resp = self.send(prep, **send_kwargs)
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/requests/sessions.py", line 573, in send
    r = adapter.send(request, **kwargs)
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/requests/adapters.py", line 337, in send
    conn = self.get_connection(request.url, proxies)
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/requests/adapters.py", line 251, in get_connection
    conn = self.poolmanager.connection_from_url(url)
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/requests/packages/urllib3/poolmanager.py", line 139, in connection_from_url
    return self.connection_from_host(u.host, port=u.port, scheme=u.scheme)
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/requests/packages/urllib3/poolmanager.py", line 125, in connection_from_host
    self.pools[pool_key] = pool
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/requests/packages/urllib3/_collections.py", line 66, in __setitem__
    _key, evicted_value = self._container.popitem(last=False)
KeyError: ('https', 'eu.wiktionary.org', 443)

Now that doesn't make much sense, as OrderedDict.popitem() only returns a KeyError if it's empty but then not with that error message. Unfortunately I can't reproduce it without doing the complete pywikibot test suite. When I only execute the tests where it occurred I don't get any failures. So I modified the output in urllib3 and returned the key as well as the content before popitem(last=False) is called (I shortened the values):

Key: ('https', 'bn.wikipedia.org', 443)
Content: OrderedDict([(('https', 'bn.wikipedia.org', 443), <requests.packages.urllib3.connectionpool.HTTPSConnectionPool object at 0x7fe483d991d0>), (('https', 'bs.wikipedia.org', 443), <…0x7fe483d99470>), (('https', 'ca.wikipedia.org', 443), <…0x7fe483da0e10>), (('https', 'cs.wikipedia.org', 443), <…0x7fe483dfc908>), (('https', 'da.wikipedia.org', 443), <…0x7fe483d98c88>), (('https', 'de.wikipedia.org', 443), <…0x7fe4911e06a0>), (('https', 'diq.wikipedia.org', 443), <…0x7fe483d6b400>), (('https', 'dsb.wikipedia.org', 443), <…0x7fe483d6bcf8>), (('https', 'en.wikipedia.org', 443), <…0x7fe483dc1da0>), (('https', 'eo.wikipedia.org', 443), <…0x7fe483d6cf28>), (('https', 'es.wikipedia.org', 443), <…0x7fe483d6b4a8>), (('https', 'fa.wikipedia.org', 443), <…0x7fe483d27278>), (('https', 'fi.wikipedia.org', 443), <…0x7fe483d6ce10>), (('https', 'fr.wikipedia.org', 443), <…0x7fe483e24cf8>), (('https', 'frr.wikipedia.org', 443), <…0x7fe483d39390>), (('https', 'ga.wikipedia.org', 443), <…0x7fe483c99668>), (('https', 'gl.wikipedia.org', 443), <…0x7fe483ca3f98>), (('https', 'als.wikipedia.org', 443), <…0x7fe483c4fcf8>), (('https', 'hu.wikipedia.org', 443), <…0x7fe483cd09e8>)])

As you can see it is not empty and the key in the KeyError is the first key in the OrderedDict. Also the key there is different from the key in the original exception I noticed so it's not a specific key that failed.

I don't think versions before Python 3.6 are affected as we had tests running on Python 3.5 (before Travis switched to 3.6 recently) and these all worked. Also not all popitem() calls in that line fail. I'm using Python 3.6.0a0 (default:d6c91b8242d2, Jul 18 2015, 16:36:01).

See also: urllib3/urllib3#680 and https://phabricator.wikimedia.org/T106212

[xZise]

Looking further into this issue, OrderedDict.pop() using the key returned from the KeyError (using eval(str(error))) also yields a KeyError. And OrderedDict.popitem() does not change the dictionary (so it's not like the KeyError is raised even though it worked).

Also it appears to be empty actually. list(OrderedDict) returns an empty list even though str(OrderedDict) does not. So maybe some operations do only remove entries from one part of the data so that popitem() still thinks it's in the cache. Now I'm not familiar with urllib3 so I'm not sure how that internal OrderedDict is used to narrow down what might cause that issue.

And additionally I tried to output keys(), items() and values() separately and suddenly I get a KeyError even when I just do str():

    conn = self.poolmanager.connection_from_url(url)
  File "/home/xzise/.pyenv/versions/3.6-dev/lib/python3.6/site-packages/requests/packages/urllib3/poolmanager.py", line 139, in connection_from_url
    return self.connection_from_host(u.host, port=u.port, scheme=u.scheme)
  File "/home/xzise/.pyenv/versions/3.6-dev/lib/python3.6/site-packages/requests/packages/urllib3/poolmanager.py", line 125, in connection_from_host
    self.pools[pool_key] = pool
  File "/home/xzise/.pyenv/versions/3.6-dev/lib/python3.6/site-packages/requests/packages/urllib3/_collections.py", line 66, in __setitem__
    __before = str(self._container)
KeyError: ('https', 'ru.wikipedia.org', 443)

[ericsnowcurrently]

Just to get this out of the way, are you running your tests against the latest beta (3)? There were some known bugs in earlier betas that have since been fixed.

[ericsnowcurrently]

Correct me if I'm wrong but the travis-ci logs [1] seem to indicate it's using Python 3.6.0a0.

[1] https://travis-ci.org/xZise/pywikibot-core/builds/71550286#L144

[xZise]

Well as I described in the opening post:

"I don't think versions before Python 3.6 are affected as we had tests running on Python 3.5 (before Travis switched to 3.6 recently) and these all worked."

Now tbh I don't know if a version of 3.5 is affected but was never tested by Travis. And if then the 3.6 branch was branched of that version. If that how it works. As I'm using pyenv I could easily test this on Python 3.5b3. By the way the last official test run on Pyhton 3.5 using Travis was using 3.5a4+: https://travis-ci.org/wikimedia/pywikibot-core/jobs/71443578#L144

[ericsnowcurrently]

Ah, sorry. I wasn't thinking past Python 3.5 (which is about to go to beta 4). While 3.6.0a0, doesn't tell us much, d6c91b8242d2 (r96935) does. That revision has all the necessary fixes to OrderedDict. I'll look into this some more. Do you get the failure consistently when running the test suite?

Also, in case you weren't aware: Python 3.5 (hence 3.6) introduces a C implementation of OrderedDict.

[xZise]

It is consistent as in it happens on every run of the test suite. But unfortunately I haven't checked if it's always happening at the same place. Luckily we have 4 builds on Travis with 3.6 and in all it happened from the beginning and got > 100 matches for “KeyError:”:

• https://travis-ci.org/wikimedia/pywikibot-core/jobs/71537432#L274
• https://travis-ci.org/wikimedia/pywikibot-core/jobs/71626596#L274
• https://travis-ci.org/wikimedia/pywikibot-core/jobs/71636529#L274
• https://travis-ci.org/wikimedia/pywikibot-core/jobs/71637809#L274
• https://travis-ci.org/xZise/pywikibot-core/builds/71550286#L274

Maybe I can do additional analysis but I'm pretty sure for me locally I didn't get failures so soon.

And no I wasn't aware about OrderedDict implemented in C. Now I haven't done tests in 3.5.0b3 (which seems to be the newest version of 3.5 available via pyenv at the moment) as it's relatively cumbersome and prevents me from doing any development on pywikibot at the same time. Anyway I still might do it and report whether I get the error too (unless OrderedDict is still implemented in Python in that version).

[ericsnowcurrently]

Thanks for the extra info. I'm going to see if I can reproduce the issue by running the pywikibot test suite locally. What's the best way to set that up? Are there instructions somewhere?

As to the C implementation, it was first released (as a special exception) in 3.5b2.

[xZise]

Yes see the tests/README.rst. And afaik do you only need to have requests and six installed.

[xZise]

Okay I did a test run on all three 3.5 betas available to me through pyenv. The beta 3 failed as Python 3.6 does that popitem() raises a KeyError. The beta 2 had the bug that popitem() does not support keyword arguments so I wasn't able to test it there. And the beta 1 works fine so it looks like the C implementation is the cause of this.

[ericsnowcurrently]

I've thus far been unsuccessful in running the pywikibot test suite. I'm guessing there are some prerequisites (e.g. an account on some wiki site). Is there a way to run the tests without network access? Also, I ran into some trouble with i18n.__file__, but hacked my way around it.

[xZise]

Oh sorry, I basically never need to install pywikibot anew so it's easy to forget but there is a submodule in scripts/i18n which needs to be cloned as well. With the following commands I could reproduce the error (and you don't even need to install requests and six):

  $ git clone --recursive  git@github.com:wikimedia/pywikibot-core.git test
  $ cd test/
  $ echo "mylang='en'" >> user-config.py
  $ echo "family='wikipedia'" >> user-config.py
  $ python setup.py test

With that you only need a network connection (as this error is in urllib3 I doubt it works without network connection) but you don't need any wiki account. If you want to test it with an account, execute “generate_user_files.py” before. Just as a note I've activated write and write failure tests but without an account these tests should not be run anyway.