503 unavailable response from datastore after app has idled for a few minutes

[heidmotron]

I've been getting this response in both production and locally (using the production datastore):

{ [Error]
  code: 503,
  metadata: Metadata { _internal_repr: {} },
  response: '' }

The error is thrown from here - https://github.com/grpc/grpc/blob/release-0_13_1/src/node/src/client.js#L411

Steps to reproduce:

1. Make a http request "/" that hits datastore
2. Wait a few minutes and don't make an http request that hits the datastore
3. Make a http request "/" that hits datastore

Expect: Datastore to return results
Actual: 503 unavailable

1. Immediately make a http request "/" that hits datastore

The datastore will work and continue to work for another few minutes.
I've deployed the bookstore sample app and it seems to have the same behavior saying "Something broke!".

Here is the code:

var gcloud = require('gcloud')({
    projectId: 'app'
});
var datastore = gcloud.datastore();

var app = express();
app.disable('etag');
app.set('trust proxy', true);


app.get('/', function(req, res, next) {
    var query = datastore.createQuery('Post').filter("Status", "staged");

    datastore.runQuery(query, function(err, posts) {
        if (err) {
            console.log(err.message)
            console.log(err.code)
            console.log(err.metadata)
            next(err)
        } else {
            res.status(200).send("Posts staged = " + posts.length)
        }
    })

});

I'm using the default app credentials and Flexible VMs. Let me know if there is any other info I could provide.

[stephenplusplus]

Thanks for reporting. Can you log err.stack as well? Off hand, I'm not sure of anything that might be causing this. @callmehiphop can you try to reproduce?

[callmehiphop]

I'm able to reproduce if I wait about 5 minutes between requests. Also, the error stack doesn't appear to give us very much.

Error
    at gcloud-node/node_modules/grpc/src/node/src/client.js:411:17

[heidmotron]

@stephenplusplus @callmehiphop - that's the same error stack I get.

I've tried a similar test using the Cloud Storage API where I grab a private file, wait, and then try it again & I do not run into the 503 issue or if I do it's handled.

[callmehiphop]

I was able to reproduce this with the Logging API, which leads me to believe that this is related to grpc. @heidmotron this would also explain why you weren't able to reproduce it via Storage.

@murgatroid99 we're seeing an issue where we make a request and wait about 5 minutes, then all subsequent requests fail. Could this be a result of the client channel going into an idle state? Any insight you could provide here would be greatly appreciated!

[heidmotron]

@callmehiphop @murgatroid99 - In the stderr of the managed vm logs I found this next to the client.js:411 error.

D0425 01:16:44.599823845 26 chttp2_transport.c:698] got goaway [0]: 73 65 73 73 69 6f 6e 5f 74 69 6d 65 64 5f 6f 75 74 'session_timed_out'

[murgatroid99]

@ctiller Does the gRPC core ever generate a message like that?

[leonardpunt]

We're experiencing the same issue in two of our applications. The errors started occurring since the 22nd of April. Our apps are using different versions of this library, v0.30.3 and v0.27.0, the error occurs in both. Furthermore, the errors didn't seem to be introduced by an update/deploy on our side. Probably something in the underlying infrastructure has changed?

[gaballard]

This is still happening in the BigTable plugin.