[python] change feed not returning all results

[mbroadst]

Hey, I'm trying to get the C++ driver to pass all tests for v2.3.4 and have run into a particularly weird case in what seems to only be my current two test rethink servers. I'm running the following python code:

import rethinkdb as r
r.connect('192.168.11.77').repl()
r.table('foo').delete().run()
c = r.table('foo').changes(squash=1000000).run(changefeed_queue_size=10)
r.table('foo').insert([{'id':0}, {'id':1}, {'id':2}, {'id':3}, {'id':4}, {'id':5}, {'id':6}]).get_field('inserted').run()
for i in range(7): print c.next()

which results in the following output:

mbroadst@retinoid:~$ python test.py
{u'old_val': None, u'new_val': {u'id': 4}}
{u'old_val': None, u'new_val': {u'id': 3}}
{u'old_val': None, u'new_val': {u'id': 1}}
{u'old_val': None, u'new_val': {u'id': 6}}
{u'old_val': None, u'new_val': {u'id': 5}}
{u'old_val': None, u'new_val': {u'id': 0}}

and then it just hangs on the last result, which never arrives unless I go into the web console of the server and issue a r.table('foo').delete() from the Data Explorer. As soon as that happens, the last entry {u'old_val': None, u'new_val': {u'id': 2}} pops into sight and the script completes execution.

Any ideas?

[danielmewes]

@mbroadst Does this go away if you lower the squash value (to let's say 1s)?

I suspect it's waiting on the squash timeout, and whether that happens or not depends more or less on random timing. If all modifications get into the first batch, they are sent immediately. But if one of them is processed slightly later, it will have to wait the full 1,000,000 seconds (or until the changefeed queue gets close to full, e.g. by generating additional changes through the delete).

Is this based on one of our tests? It seems fragile, and I'm not sure if it should be there.

Also pinging @mlucy in case I'm misunderstanding something.

[mbroadst]

@danielmewes this is actually one of the rql_test suite tests: https://github.com/rethinkdb/rethinkdb/blob/next/test/rql_test/src/limits.yaml#L106.

It looks like this works just fine on my ubuntu trusty 14.04 VM, so the culprit might be OSX 10.10.5.. somehow

[danielmewes]

As far as my current understanding goes, I think that the culprit is that the test is bad. It tests something that we don't guarantee, and relies on timing and undefined behavior.

@mlucy might know more about what this test was meant to test originally.

[mlucy]

I think this test is meant to check whether or not the changefeed queue size actually triggers documents being sent. I think @danielmewes is right that it doesn't work, though; I think it needs to read an initial empty batch before doing the inserts.

[mbroadst]

Okay well that makes me feel a little better! There are a number of similar tests that fail for me, so I might as well list them here:

• https://github.com/rethinkdb/rethinkdb/blob/next/test/rql_test/src/limits.yaml#L73
• https://github.com/rethinkdb/rethinkdb/blob/next/test/rql_test/src/limits.yaml#L85
• https://github.com/rethinkdb/rethinkdb/blob/next/test/rql_test/src/limits.yaml#L106
• https://github.com/rethinkdb/rethinkdb/blob/next/test/rql_test/src/limits.yaml#L118

[mbroadst]

I've got a few more here:

• https://github.com/rethinkdb/rethinkdb/blob/next/test/rql_test/src/mutation/insert.yaml#L183
  I'm actually pretty sure this test isn't run because it's not valid python (true != True), but also because when converting it to valid python I get the same results as the C++ and javascript drivers (what you would expect): the returned changes are not an empty array []. The aforementioned true issue is present in a number of other tests, I wonder if these are silently failing somehow?
• https://github.com/rethinkdb/rethinkdb/blob/next/test/rql_test/src/mutation/insert.yaml#L179
  This test is just sort of a bummer because it depends on data left in the table from the previous run (see the expected result as having a "Duplicate primary key id"), when that's not really critical to the functionality it's purportedly testing.
• https://github.com/rethinkdb/rethinkdb/blob/next/test/rql_test/src/changefeeds/table.yaml#L66
  This is the final hurdle to full test suite compliance for the C++ driver, and I can't find any reference whatsoever to there being a hard coded array limit size of 90 in the python driver. If someone could point me to that I would really appreciate it, and we can ensure the same guarantee in the C++ driver.

[danielmewes]

Interesting observation regarding the true thing. I'd like @larkost to take a look at this.

[danielmewes]

Regarding the test in table.yaml: The limit is not in the Python driver, but is set for the changefeed a few lines above: https://github.com/rethinkdb/rethinkdb/blob/next/test/rql_test/src/changefeeds/table.yaml#L61

I'm not sure why we're only fetching 90 values though, and why that's correct. The limit is 100, so it seems to me as if we could get 100 valid results first, and only then see the error.

Additionally, this test again seems timing-sensitive, because all of our drivers prefetch batches on cursors (including changefeeds).
So if the prefetch request is processed by the server before the changefeed exceeds the limit, it will send back up to 100 valid results. We're inserting 200 rows, so the next batch is still going to overflow, but it seems like we'll actually need to fetch up to 200 rows (and not just 90) to guarantee that we see the error.

[mbroadst]

oh right that was a silly oversight on my part. yeah I agree with your observation, it's definitely failing for me here because a valid number of results is in fact being returned (perhaps we're not buffering as aggressively in the C++ driver presently)

[larkost]

Looking at the first one there is no problem with true != True since we have a line in the polygon driver (grr) that takes care of that. The reason that one is passing in Python is because we set the expected value to partial({'changes':[]}), so we are only looking for a dict that has a value changes. And the output is:

{u'first_error': u'Duplicate primary keyid:\n{\n\t"id":\t101,\n\t"ordered-num":\t1\n}\n{\n\t"id":\t101,\n\t"ordered-num":\t1\n}', u'errors': 99, u'deleted': 0, u'changes': [], u'unchanged': 0, u'skipped': 0, u'replaced': 0, u'inserted': 0}

Since that has that value, we pass... very much not what the test writer was expecting I am sure, but not a general problem in our testing system.

@nighelles those lines have your name on them, can you rethink them a bit (yes... I am on a roll).

[mbroadst]

@larkost yeah it seems like a ton of these tests inadvertently depend on or are affected by existing data in the table. It does make me wonder why our tests are getting different results though, I should look into that since we aren't cleaning the tables between runs