Google-cloud-go: pubsub: Failed to decode ("google.rpc.debuginfo-bin" .. messages

[cristiangraz]

I keep seeing what seems to be debug output when using the pubsub library and making calls that return grpc errors (i.e. subscription.Exists, CreateSubscription when subscription does not exist). I am getting this debug output that is base64 encoded twice.

2017/03/14 00:46:01 Failed to decode ("google.rpc.debuginfo-bin", "Q2xkamIyMHVaMjl2...REDACTED...t3TURNMw"): illegal base64 data at input byte 1988

If I run that string through this

<string> | base64 --decode | base64 --decode

I get this:

Wcom.google.cloud.pubsub.server.config.megastore.NameDaoUtil.lookup(NameDaoUtil.java:65)
?com.google.cloud.pubsub.server.config.megastore.ResourceConfigDaoTaskFactory$LookupIdTask.call(ResourceConfigDaoTaskFactory.java:563)
?com.google.cloud.pubsub.server.config.megastore.ResourceConfigDaoTaskFactory$LookupIdTask.call(ResourceConfigDaoTaskFactory.java:552)
Zcom.google.storage.megastore.tools.JobRetryHelper.callWithRetries(JobRetryHelper.java:401)
icom.google.cloud.pubsub.server.config.megastore.MegastoreRetryingTask.call(MegastoreRetryingTask.java:22)
?com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:111)
Rcom.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:61)
fcom.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:75)
Ojava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
Ojava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)9<subscription name redacted> not found in project <project id redacted>`

I tried setting GRPC_VERBOSITY=ERROR but the warnings still appear. Is this a bug, or is there some way to disable this? I can't find this string across any of the google repos or google searches/slack channels. I would expect not to see these since I am looking for and handling grpc codes such as ALREADY_EXISTS.

The only reference I've been able to find to the string "google.rpc.debuginfo-bin" was in this thread: https://github.com/GoogleCloudPlatform/google-cloud-go/issues/499#issuecomment-276446369

I've seen this on a few different commits, but I'm currently running the latest https://github.com/GoogleCloudPlatform/google-cloud-go/commit/0bee953ffbf6fda3be3f56f1e9578f16a1e978a4.

Here is a snippet that's triggering this warning (although it seems to occur generally when a call returns a grpc code)

sub := client.Subscription(subscription)
if exists, err := sub.Exists(ctx); err != nil {
    return nil, err
} else if !exists {
    if _, err := client.CreateSubscription(ctx, subscription, topic, 10*time.Second, nil); err != nil {
        return nil, err
    }
}

Not sure if it's relevant, but I'm authenticating with a JSON service key by passing an option.ClientOption into pubsub.NewClient (google.JWTConfigFromJSON + option.WithTokenSource)

[aubm]

I get the same error when I configure the client with a service account json key file.
It seems that explicitly adding the service account in the topic or subscription permissions makes it work again. I will continue my investigations tomorrow (UTC+1).

[bradleyfalzon]

I'm getting stacks of these (one every couple of minutes) at the moment and can decode with OPs suggestion:

icom.google.cloud.pubsub.server.transport.TransportUtils.createRpcFailureException(TransportUtils.java:19)
lcom.google.cloud.pubsub.server.transport.goops.GoopsSubscriberProxy$9.failure(GoopsSubscriberProxy.java:602)
Ycom.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher$1.runInContext(RpcStub.java:853)
Qcom.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:460)
Gcom.google.tracing.CurrentContext.runInContext(CurrentContext.java:293)
pcom.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:319)
icom.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:311)
Ocom.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:457)
Vcom.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher.runCallback(RpcStub.java:889)
Vcom.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher.rpcFinished(RpcStub.java:899)�DEADLINE_EXCEEDED: RPC deadline: 89.000000, Error Text: /SubscriberService.ModifyAckDeadline to 127.0.0.1:14899 [DEADLINE_EXCEEDED] Deadline=89.0s, Error Detail: Deadlibase64: invalid input

Based on my error, I think my issue is a little different.

Mar 22 15:01:14 www1 gopherci[20015]: 2017/03/22 15:01:14 Failed to decode ("google.rpc.debuginfo-bin", "Q21samIyMHVaMjl2WjJ4bExtTnNiM1ZrTG5CMVluTjFZaTV6WlhKMlpYSXVkSEpoYm5Od2IzSjBMbFJ5WVc1emNHOXl
kRlYwYVd4ekxtTnlaV0YwWlZKd1kwWmhhV3gxY21WRmVHTmxjSFJwYjI0b1ZISmhibk53YjNKMFZYUnBiSE11YW1GMllUb3hPU2tLYW1OdmJTNW5iMjluYkdVdVkyeHZkV1F1Y0hWaWMzVmlMbk5sY25abGNpNTBjbUZ1YzNCdmNuUXVaMjl2Y0hNdVIyOXZjSE5
RZFdKc2FYTm9aWEpRY205NGVTUXhMbVpoYVd4MWNtVW9SMjl2Y0hOUWRXSnNhWE5vWlhKUWNtOTRlUzVxWVhaaE9qRXhOU2tLV1dOdmJTNW5iMjluYkdVdWJtVjBMbkp3WXpNdVkyeHBaVzUwTGxKd1kxTjBkV0lrVW5CalEyRnNiR0poWTJ0RWFYTndZWFJqYUd
WeUpERXVjblZ1U1c1RGIyNTBaWGgwS0ZKd1kxTjBkV0l1YW1GMllUbzROVE1wQ2xGamIyMHVaMjl2WjJ4bExuUnlZV05wYm1jdVZISmhZMlZEYjI1MFpYaDBKRlJ5WVdObFEyOXVkR1Y0ZEZKMWJtNWhZbXhsSkRFdWNuVnVLRlJ5WVdObFEyOXVkR1Y0ZEM1cVl
YWmhPalEyTUNrS1IyTnZiUzVuYjI5bmJHVXVkSEpoWTJsdVp5NURkWEp5Wlc1MFEyOXVkR1Y0ZEM1eWRXNUpia052Ym5SbGVIUW9RM1Z5Y21WdWRFTnZiblJsZUhRdWFtRjJZVG95T1RNcENuQmpiMjB1WjI5dloyeGxMblJ5WVdOcGJtY3VWSEpoWTJWRGIyNTB
aWGgwSkVGaWMzUnlZV04wVkhKaFkyVkRiMjUwWlhoMFEyRnNiR0poWTJzdWNuVnVTVzVKYm1obGNtbDBaV1JEYjI1MFpYaDBUbTlWYm5KbFppaFVjbUZqWlVOdmJuUmxlSFF1YW1GMllUb3pNVGtwQ21samIyMHVaMjl2WjJ4bExuUnlZV05wYm1jdVZISmhZMlZ
EYjI1MFpYaDBKRUZpYzNSeVlXTjBWSEpoWTJWRGIyNTBaWGgwUTJGc2JHSmhZMnN1Y25WdVNXNUpibWhsY21sMFpXUkRiMjUwWlhoMEtGUnlZV05sUTI5dWRHVjRkQzVxWVhaaE9qTXhNU2tLVDJOdmJTNW5iMjluYkdVdWRISmhZMmx1Wnk1VWNtRmpaVU52Ym5
SbGVIUWtWSEpoWTJWRGIyNTBaWGgwVW5WdWJtRmliR1V1Y25WdUtGUnlZV05sUTI5dWRHVjRkQzVxWVhaaE9qUTFOeWtLVm1OdmJTNW5iMjluYkdVdWJtVjBMbkp3WXpNdVkyeHBaVzUwTGxKd1kxTjBkV0lrVW5CalEyRnNiR0poWTJ0RWFYTndZWFJqYUdWeUx
uSjFia05oYkd4aVlXTnJLRkp3WTFOMGRXSXVhbUYyWVRvNE9Ea3BDbFpqYjIwdVoyOXZaMnhsTG01bGRDNXljR016TG1Oc2FXVnVkQzVTY0dOVGRIVmlKRkp3WTBOaGJHeGlZV05yUkdsemNHRjBZMmhsY2k1eWNHTkdhVzVwYzJobFpDaFNjR05UZEhWaUxtcGh
kbUU2T0RrNUtSS3FBVVJGUVVSTVNVNUZYMFZZUTBWRlJFVkVPaUJTVUVNZ1pHVmhaR3hwYm1VNklERXdMakF3TURBd01Dd2dSWEp5YjNJZ1ZHVjRkRG9nTDFCMVlteHBjMmhsY2xObGNuWnBZMlV1VUhWaWJHbHphRUpoZEdOb0lIUnZJREV5Tnk0d0xqQXVNVG9
5TlRjeU9TQmJSRVZCUkV4SlRrVmZSVmhEUlVWRVJVUmRJRVJsWVdSc2FXNWxQVEV3TGpCekxDQkZjbkp2Y2lCRVpYUmhhV3c2SUVSbFlXUnNhVzVsUFRFd0xqQno")
Mar 22 15:01:14 www1 gopherci[20015]: : illegal base64 data at input byte 1976
Mar 22 15:01:14 www1 gopherci[20015]: 2017/03/22 15:01:14 Failed to decode ("google.rpc.debuginfo-bin", "Q21samIyMHVaMjl2WjJ4bExtTnNiM1ZrTG5CMVluTjFZaTV6WlhKMlpYSXVkSEpoYm5Od2IzSjBMbFJ5WVc1emNHOXl
kRlYwYVd4ekxtTnlaV0YwWlZKd1kwWmhhV3gxY21WRmVHTmxjSFJwYjI0b1ZISmhibk53YjNKMFZYUnBiSE11YW1GMllUb3hPU2tLYW1OdmJTNW5iMjluYkdVdVkyeHZkV1F1Y0hWaWMzVmlMbk5sY25abGNpNTBjbUZ1YzNCdmNuUXVaMjl2Y0hNdVIyOXZjSE5
RZFdKc2FYTm9aWEpRY205NGVTUXhMbVpoYVd4MWNtVW9SMjl2Y0hOUWRXSnNhWE5vWlhKUWNtOTRlUzVxWVhaaE9qRXhOU2tLV1dOdmJTNW5iMjluYkdVdWJtVjBMbkp3WXpNdVkyeHBaVzUwTGxKd1kxTjBkV0lrVW5CalEyRnNiR0poWTJ0RWFYTndZWFJqYUd
WeUpERXVjblZ1U1c1RGIyNTBaWGgwS0ZKd1kxTjBkV0l1YW1GMllUbzROVE1wQ2xGamIyMHVaMjl2WjJ4bExuUnlZV05wYm1jdVZISmhZMlZEYjI1MFpYaDBKRlJ5WVdObFEyOXVkR1Y0ZEZKMWJtNWhZbXhsSkRFdWNuVnVLRlJ5WVdObFEyOXVkR1Y0ZEM1cVl
YWmhPalEyTUNrS1IyTnZiUzVuYjI5bmJHVXVkSEpoWTJsdVp5NURkWEp5Wlc1MFEyOXVkR1Y0ZEM1eWRXNUpia052Ym5SbGVIUW9RM1Z5Y21WdWRFTnZiblJsZUhRdWFtRjJZVG95T1RNcENuQmpiMjB1WjI5dloyeGxMblJ5WVdOcGJtY3VWSEpoWTJWRGIyNTB
aWGgwSkVGaWMzUnlZV04wVkhKaFkyVkRiMjUwWlhoMFEyRnNiR0poWTJzdWNuVnVTVzVKYm1obGNtbDBaV1JEYjI1MFpYaDBUbTlWYm5KbFppaFVjbUZqWlVOdmJuUmxlSFF1YW1GMllUb3pNVGtwQ21samIyMHVaMjl2WjJ4bExuUnlZV05wYm1jdVZISmhZMlZ
EYjI1MFpYaDBKRUZpYzNSeVlXTjBWSEpoWTJWRGIyNTBaWGgwUTJGc2JHSmhZMnN1Y25WdVNXNUpibWhsY21sMFpXUkRiMjUwWlhoMEtGUnlZV05sUTI5dWRHVjRkQzVxWVhaaE9qTXhNU2tLVDJOdmJTNW5iMjluYkdVdWRISmhZMmx1Wnk1VWNtRmpaVU52Ym5
SbGVIUWtWSEpoWTJWRGIyNTBaWGgwVW5WdWJtRmliR1V1Y25WdUtGUnlZV05sUTI5dWRHVjRkQzVxWVhaaE9qUTFOeWtLVm1OdmJTNW5iMjluYkdVdWJtVjBMbkp3WXpNdVkyeHBaVzUwTGxKd1kxTjBkV0lrVW5CalEyRnNiR0poWTJ0RWFYTndZWFJqYUdWeUx
uSjFia05oYkd4aVlXTnJLRkp3WTFOMGRXSXVhbUYyWVRvNE9Ea3BDbFpqYjIwdVoyOXZaMnhsTG01bGRDNXljR016TG1Oc2FXVnVkQzVTY0dOVGRIVmlKRkp3WTBOaGJHeGlZV05yUkdsemNHRjBZMmhsY2k1eWNHTkdhVzVwYzJobFpDaFNjR05UZEhWaUxtcGh
kbUU2T0RrNUtSS3FBVVJGUVVSTVNVNUZYMFZZUTBWRlJFVkVPaUJTVUVNZ1pHVmhaR3hwYm1VNklERXdMakF3TURBd01Dd2dSWEp5YjNJZ1ZHVjRkRG9nTDFCMVlteHBjMmhsY2xObGNuWnBZMlV1VUhWaWJHbHphRUpoZEdOb0lIUnZJREV5Tnk0d0xqQXVNVG9
4TkRVME5pQmJSRVZCUkV4SlRrVmZSVmhEUlVWRVJVUmRJRVJsWVdSc2FXNWxQVEV3TGpCekxDQkZjbkp2Y2lCRVpYUmhhV3c2SUVSbFlXUnNhVzVsUFRFd0xqQno")
Mar 22 15:01:14 www1 gopherci[20015]: : illegal base64 data at input byte 1976
Mar 22 15:01:24 www1 gopherci[20015]: 2017/03/22 15:01:24 Failed to decode ("google.rpc.debuginfo-bin", "Q21samIyMHVaMjl2WjJ4bExtTnNiM1ZrTG5CMVluTjFZaTV6WlhKMlpYSXVkSEpoYm5Od2IzSjBMbFJ5WVc1emNHOXl
kRlYwYVd4ekxtTnlaV0YwWlZKd1kwWmhhV3gxY21WRmVHTmxjSFJwYjI0b1ZISmhibk53YjNKMFZYUnBiSE11YW1GMllUb3hPU2tLYW1OdmJTNW5iMjluYkdVdVkyeHZkV1F1Y0hWaWMzVmlMbk5sY25abGNpNTBjbUZ1YzNCdmNuUXVaMjl2Y0hNdVIyOXZjSE5
RZFdKc2FYTm9aWEpRY205NGVTUXhMbVpoYVd4MWNtVW9SMjl2Y0hOUWRXSnNhWE5vWlhKUWNtOTRlUzVxWVhaaE9qRXhOU2tLV1dOdmJTNW5iMjluYkdVdWJtVjBMbkp3WXpNdVkyeHBaVzUwTGxKd1kxTjBkV0lrVW5CalEyRnNiR0poWTJ0RWFYTndZWFJqYUd
WeUpERXVjblZ1U1c1RGIyNTBaWGgwS0ZKd1kxTjBkV0l1YW1GMllUbzROVE1wQ2xGamIyMHVaMjl2WjJ4bExuUnlZV05wYm1jdVZISmhZMlZEYjI1MFpYaDBKRlJ5WVdObFEyOXVkR1Y0ZEZKMWJtNWhZbXhsSkRFdWNuVnVLRlJ5WVdObFEyOXVkR1Y0ZEM1cVl
YWmhPalEyTUNrS1IyTnZiUzVuYjI5bmJHVXVkSEpoWTJsdVp5NURkWEp5Wlc1MFEyOXVkR1Y0ZEM1eWRXNUpia052Ym5SbGVIUW9RM1Z5Y21WdWRFTnZiblJsZUhRdWFtRjJZVG95T1RNcENuQmpiMjB1WjI5dloyeGxMblJ5WVdOcGJtY3VWSEpoWTJWRGIyNTB
aWGgwSkVGaWMzUnlZV04wVkhKaFkyVkRiMjUwWlhoMFEyRnNiR0poWTJzdWNuVnVTVzVKYm1obGNtbDBaV1JEYjI1MFpYaDBUbTlWYm5KbFppaFVjbUZqWlVOdmJuUmxlSFF1YW1GMllUb3pNVGtwQ21samIyMHVaMjl2WjJ4bExuUnlZV05wYm1jdVZISmhZMlZ
EYjI1MFpYaDBKRUZpYzNSeVlXTjBWSEpoWTJWRGIyNTBaWGgwUTJGc2JHSmhZMnN1Y25WdVNXNUpibWhsY21sMFpXUkRiMjUwWlhoMEtGUnlZV05sUTI5dWRHVjRkQzVxWVhaaE9qTXhNU2tLVDJOdmJTNW5iMjluYkdVdWRISmhZMmx1Wnk1VWNtRmpaVU52Ym5
SbGVIUWtWSEpoWTJWRGIyNTBaWGgwVW5WdWJtRmliR1V1Y25WdUtGUnlZV05sUTI5dWRHVjRkQzVxWVhaaE9qUTFOeWtLVm1OdmJTNW5iMjluYkdVdWJtVjBMbkp3WXpNdVkyeHBaVzUwTGxKd1kxTjBkV0lrVW5CalEyRnNiR0poWTJ0RWFYTndZWFJqYUdWeUx
uSjFia05oYkd4aVlXTnJLRkp3WTFOMGRXSXVhbUYyWVRvNE9Ea3BDbFpqYjIwdVoyOXZaMnhsTG01bGRDNXljR016TG1Oc2FXVnVkQzVTY0dOVGRIVmlKRkp3WTBOaGJHeGlZV05yUkdsemNHRjBZMmhsY2k1eWNHTkdhVzVwYzJobFpDaFNjR05UZEhWaUxtcGh
kbUU2T0RrNUtSS3FBVVJGUVVSTVNVNUZYMFZZUTBWRlJFVkVPaUJTVUVNZ1pHVmhaR3hwYm1VNklERXdMakF3TURBd01Dd2dSWEp5YjNJZ1ZHVjRkRG9nTDFCMVlteHBjMmhsY2xObGNuWnBZMlV1VUhWaWJHbHphRUpoZEdOb0lIUnZJREV5Tnk0d0xqQXVNVG9
5TlRRMk15QmJSRVZCUkV4SlRrVmZSVmhEUlVWRVJVUmRJRVJsWVdSc2FXNWxQVEV3TGpCekxDQkZjbkp2Y2lCRVpYUmhhV3c2SUVSbFlXUnNhVzVsUFRFd0xqQno")
Mar 22 15:01:24 www1 gopherci[20015]: : illegal base64 data at input byte 1976

EDIT: appears to be an service reliability issue, sorry for the noise.

[ehmo]

I'm seeing the same thing. My honest guess is that the issue in within the pubsub backed.

base64: invalid input

icom.google.cloud.pubsub.server.transport.TransportUtils.createRpcFailureException(TransportUtils.java:19)
jcom.google.cloud.pubsub.server.transport.goops.GoopsPublisherProxy$1.failure(GoopsPublisherProxy.java:115)
Ycom.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher$1.runInContext(RpcStub.java:853)
Qcom.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:460)
Gcom.google.tracing.CurrentContext.runInContext(CurrentContext.java:293)
pcom.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:319)
icom.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:311)
Ocom.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:457)
Vcom.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher.runCallback(RpcStub.java:889)
Vcom.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher.rpcFinished(RpcStub.java:899)�DEADLINE_EXCEEDED: RPC deadline: 10.000000, Error Text: /PublisherService.PublishBatch to 127.0.0.1:14392 [DEADLINE_EXCEEDED] Deadline=10.0s, Error Detail: Deadline=10.0

[ehmo]

Here is more on the issue

[academician]

Chiming in that I'm seeing the same thing. Base64 decodes to:

icom.google.cloud.pubsub.server.transport.TransportUtils.createRpcFailureException(TransportUtils.java:19)
jcom.google.cloud.pubsub.server.transport.goops.GoopsPublisherProxy$1.failure(GoopsPublisherProxy.java:115)
Ycom.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher$1.runInContext(RpcStub.java:853)
Qcom.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:460)
Gcom.google.tracing.CurrentContext.runInContext(CurrentContext.java:293)
pcom.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:319)
icom.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:311)
Ocom.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:457)
Vcom.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher.runCallback(RpcStub.java:889)
Vcom.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher.rpcFinished(RpcStub.java:899)?DEADLINE_EXCEEDED: RPC deadline: 10.000000, Error Text: /PublisherService.PublishBatch to 127.0.0.1:14605 [DEADLINE_EXCEEDED] Deadline=10.0s, Error Detail: Deadline=10

[Yugloocamai]

Bump

[academician]

https://status.cloud.google.com/incident/cloud-pubsub/17001

Mar 21, 2017 22:40
The issue with Pub/Sub high latency has been resolved for all affected projects as of 22:02 US/Pacific. We will conduct an internal investigation of this issue and make appropriate improvements to our systems to help prevent or minimize future recurrence.

It does seem to be resolved on my end.

[cristiangraz]

It seems others are seeing this debug output, however, the recent comments seem related to to the latency issue in pubsub. Whatever is causing the debug output may be related with the original issue, but just want to confirm I'm still seeing the issue I initially reported.

[bits01]

It seems this happens for any gRPC error, e.g. trying to create a sub that already exists. The returned error works OK, you can call grpc.Code(err) and it behaves, so it looks like harmless debug output, but I'd rather not get my logs spammed with it.

[jba]

I believe this has been resolved. Reopen if I'm wrong.