testInsertAllWithSuffix is failing

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

@jtigani

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?

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?

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.)

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.

@jcondit

/cc @jcondit

Will summon the appropriate experts...

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?

@jcondit

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.

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.

@seanchen-google

@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).

Fair enough. I've created an internal bug to update the template tables documentation to indicate the potential for delay between insert and table creation.