PubSub with 'cloud-builds' topic often produces unack'ed messages

So we've been using PubSub for receiving GCB events for a while.

• We have 4 subscribers to our subscription, so they can split the workload.
• The subscribers are identical and written using the official C# client
• The subscribers use the default settings, we configure that only 1 thread should be pulling.
• They are running as a HostedService in AspNetCore inside Kubernetes.
• The subscriber application has only that one responsibility
• This application is deployed a couple of times every week since it's bundle with a more heavy use api.

The issue we are facing is this:

When looking at our Kibana logs we sometimes see what appears to a delayed of the pubs message of 1 or more minutes (notice that QUEUED has a later timestamp than WORKING).

However looking at the publishTime it is clear that problem is not that the event is published later, but rather that it is handled by our code later.

Now if we look at the PubSub graphs we get:

Which confirms that there indeed WAS an incident where message where not acked.

This explains why we are seeing the delayed handling of the message :).

But it does not explain WHY we appear to exceed the deadline of 60 seconds.

• There are no errors / exceptions anywhere to be found
• We are using the C# client in a standard way (defaults)

Now here is where it gets interesting, I discovered that if I do a PURGE messages using the google UI, everything seems to run smoothly for a while (1-3 days). But then I happens again.

Now if we look at the metrics across all the instances when the issue occurs (this is from another incident) we are at no point in time over 200ms of computation time:

Thoughts:

• We are misunderstanding something basic about the pubsub ack configuration
• Maybe the deploys we do somehow leads the subscription to think that there are still active subscribers and therefore it awaits them to fail before trying the next subscriber? This is indicated by the PURGE reaction, however I have no way of inspecting how many subscribers currently are registered with the subscription and I can't see a bug in the code that could imply this.
• Looking at the metrics the problem is not with our code. However there might be something with the official client default config / bug.

Im really puzzled and im missing insights into what is going on inside the pubsub clusters and the official client. Some tracing from the client would be nice or query tools for pubsub like the ones we have with our Kafka clusters.

The code:

public class GoogleCloudBuildHostedService : BackgroundService
{
    ...
    private async Task<SubscriberClient> BuildSubscriberClient()
    {
        var subscriptionToUse = $"{_subscriptionName}";
        var subscriptionName = new SubscriptionName(_projectId,subscriptionToUse);
        var settings = new SubscriberServiceApiSettings();
        var client = new SubscriberClient.ClientCreationSettings(1,
            credentials: GoogleCredentials.Get().UnderlyingCredential.ToChannelCredentials(),
            subscriberServiceApiSettings: settings);
        return await SubscriberClient.CreateAsync(subscriptionName, client);
    }

    protected override async Task ExecuteAsync(CancellationToken cancellationToken)
    {
        await Task.Yield();

        cancellationToken.Register(() => _log.Info("Consumer thread stopping."));

        while (cancellationToken.IsCancellationRequested == false)
        {
            try
            {
                _log.Info($"Consumer starting...");

                var client = await BuildSubscriberClient();
                await client.StartAsync((msg, cancellationToken) =>
                {
                    using (eventTimer.NewTimer())
                    {
                        try
                        {
                            ...
                        }
                        catch (Exception e)
                        {
                            _log.Error(e);
                        }
                    }

                    return Task.FromResult(SubscriberClient.Reply.Ack);
                });

                await client.StopAsync(cancellationToken);

                await Task.Delay(TimeSpan.FromSeconds(10), cancellationToken);
            }
            catch (Exception e)
            {
                _log.Info($"Consumer failed: {e.Message}");
            }
        }
        _log.Info($"Consumer stopping...");
    }
}

Hope someone out there in the great big void can enlighten me :).

Kind regards Christian

UPDATE

So I looked into one of the cases again, and here below we see:

• the same instance of the application handling messages from the same topic and subscription.
• there's 1 client thread only configured

Notice that at 15:23:04 and 15:23:10 there's 2 messages handled at the same time of publication, now 2 minutes later a message that was published at 15:23:07 is handled. And in the mean time 2 other messages are being handled.

So why is a message published at 15:23:07 not handled until 15:25:25, when other messages arrive in the mean time?