testInsertAllWithSuffix is failing

[ajkannan]

The BigQuery integration test for insertAllWithSuffix gives the following error in Travis CI:

Running com.google.gcloud.bigquery.ITBigQueryTest
Tests run: 24, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 101.531 sec <<< FAILURE! - in com.google.gcloud.bigquery.ITBigQueryTest
testInsertAllWithSuffix(com.google.gcloud.bigquery.ITBigQueryTest)  Time elapsed: 0.418 sec  <<< FAILURE!
java.lang.AssertionError: null
    at org.junit.Assert.fail(Assert.java:86)
    at org.junit.Assert.assertTrue(Assert.java:41)
    at org.junit.Assert.assertNotNull(Assert.java:712)
    at org.junit.Assert.assertNotNull(Assert.java:722)
    at com.google.gcloud.bigquery.ITBigQueryTest.testInsertAllWithSuffix(ITBigQueryTest.java:508)
Results :
Failed tests: 
  ITBigQueryTest.testInsertAllWithSuffix:508 null
Tests run: 24, Failures: 1, Errors: 0, Skipped: 0

[aozarov]

Looks like this is a flaky test.
I managed to get it pass and fail (using different account and on my desktop).

@jtigani Is there an expected delay between the automatic creation of suffixed table and to be able to get information about it?

[mziccard]

Mmmm this is unpleasant. Sorry for pushing it, I did not experience the error locally, I run the test 10 times now and it failed eventually. Should we remove the integration test while we clarify this?

[aozarov]

Did you manage to understand why it failed? Did it fail due to some delay or a failure to insert?
Yes, we should make the test pass (by adding a delay or a retry if helps and if not then disable it for now.)

[mziccard]

I checked and it seems that eventually the table is created. My guess is that this happen with some delay. I could not find any reference to this delay in the docs. I will put the failing code inside a loop+delay and that should do it until we figure out what is going on.

[mziccard]

/cc @jcondit

[jcondit]

Will summon the appropriate experts...

[seanchen-google]

In general table creation should happen O(seconds) after the first insert, but occasionally transient errors will result in O(minutes) delay.

If you're consistently seeing more than a few seconds of delay, then there's likely a bug somewhere. Do you have any statistics on what you're seeing?

[mziccard]

Thanks @jcondit and @seanchen-google for your replies. Just to make sure the scenario is clear, what we do in our test is basically:

POST https://www.googleapis.com/bigquery/v2/projects/projectId/datasets/datasetId/tables/tableId/insertAll

and specify a templateSuffix value in the request body. Once this request completes we do

GET https://www.googleapis.com/bigquery/v2/projects/projectId/datasets/datasetId/tables/tableId

The first POST succeeds and the response contains no insertErrors. The following GET happens to return 404 sometimes:

{
 "error": {
  "errors": [
   {
    "domain": "global",
    "reason": "notFound",
    "message": "Not found: Table is-websockets:gcloud_test_dataset_temp_188d94b2_8371_4bf2_b88c_3d2c2d3671f9.test_insert_all_with_suffix_table_suffix"
   }
  ],
  "code": 404,
  "message": "Not found: Table is-websockets:gcloud_test_dataset_temp_188d94b2_8371_4bf2_b88c_3d2c2d3671f9.test_insert_all_with_suffix_table_suffix"
 }
}

Checking with the web console I see that after a while the table is created and contains the expected data. Is this latency in table's creation expected and documented somewhere? If it's not I really think it should.

[seanchen-google]

It's somewhat loosely documented as part of the "Data Availability" section:

"Streamed data is available for real-time analysis within a few seconds of the first streaming insertion into a table."

Admittedly, that section may not be easily connected to the implications on template tables...

The primary reason we can't get more specific/tight w.r.t. latencies is that we don't perform creation operations in-line with insertion requests (doing so would have many potential negative performance implications). We respond as soon as data is validated/durably stored within our backend... Table creation requires global/transactional semantics, and thus suffers from higher average latencies that we don't want impacting the direct insert path.

Hopefully that makes sense.

In any case, applying a time bounded retry on tables get of ~10s should capture the expected case, and should very rarely fail. Consistent failures with a 10s retry window would be indicative of a problem on our end.

[aozarov]

@seanchen-google Thank you for your response.

I think that tying this behavior to the "Data Availability" section is less than "loosely documented" as here we are talking about metadata that is not available and not data.

I understand that this is expected and we can probably close this issue after #521 was merged, however I do think this needs to be described in the documentation associated with Automatic table creation and the templateSuffix settings (including in gcloud-java).