{"action":"opened","issue":{"url":"https://api.github.com/repos/GoogleCloudPlatform/google-cloud-go/issues/1059","repository_url":"https://api.github.com/repos/GoogleCloudPlatform/google-cloud-go","labels_url":"https://api.github.com/repos/GoogleCloudPlatform/google-cloud-go/issues/1059/labels{/name}","comments_url":"https://api.github.com/repos/GoogleCloudPlatform/google-cloud-go/issues/1059/comments","events_url":"https://api.github.com/repos/GoogleCloudPlatform/google-cloud-go/issues/1059/events","html_url":"https://github.com/GoogleCloudPlatform/google-cloud-go/issues/1059","id":340642589,"node_id":"MDU6SXNzdWUzNDA2NDI1ODk=","number":1059,"title":"PubSub: Subscription.Receive returns without an error","user":{"login":"krzysztofdrys","id":6791659,"node_id":"MDQ6VXNlcjY3OTE2NTk=","avatar_url":"https://avatars0.githubusercontent.com/u/6791659?v=4","gravatar_id":"","url":"https://api.github.com/users/krzysztofdrys","html_url":"https://github.com/krzysztofdrys","followers_url":"https://api.github.com/users/krzysztofdrys/followers","following_url":"https://api.github.com/users/krzysztofdrys/following{/other_user}","gists_url":"https://api.github.com/users/krzysztofdrys/gists{/gist_id}","starred_url":"https://api.github.com/users/krzysztofdrys/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/krzysztofdrys/subscriptions","organizations_url":"https://api.github.com/users/krzysztofdrys/orgs","repos_url":"https://api.github.com/users/krzysztofdrys/repos","events_url":"https://api.github.com/users/krzysztofdrys/events{/privacy}","received_events_url":"https://api.github.com/users/krzysztofdrys/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2018-07-12T13:39:59Z","updated_at":"2018-07-12T13:39:59Z","closed_at":null,"author_association":"NONE","body":"## Client\r\nPubSub\r\n\r\n```\r\n[[projects]]\r\n  name = \"cloud.google.com/go\"\r\n  packages = [\r\n    \"compute/metadata\",\r\n    \"iam\",\r\n    \"internal/optional\",\r\n    \"internal/version\",\r\n    \"pubsub\",\r\n    \"pubsub/apiv1\",\r\n    \"pubsub/internal/distribution\"\r\n  ]\r\n  revision = \"777200caa7fb8936aed0f12b1fd79af64cc83ec9\"\r\n  version = \"v0.24.0\"\r\n```\r\n## Describe Your Environment\r\nAlipne Docker, deployed in kubernetes in GKE\r\n\r\n## Expected Behavior\r\nAccording to documentation:\r\n```\r\n// Receive calls f with the outstanding messages from the subscription.\r\n// It blocks until ctx is done, or the service returns a non-retryable error.\r\n```\r\n\r\n## Actual Behavior\r\n`Receive` returns without an error after about 1h. \r\n\r\n## More info\r\nThis issue was introduced somewhere between 0.22 and 0.24. In other words, when I switch to 0.22, I cannot observe this problem.\r\n\r\n```\r\n[[projects]]\r\n  name = \"cloud.google.com/go\"\r\n  packages = [\r\n    \"compute/metadata\",\r\n    \"iam\",\r\n    \"internal/optional\",\r\n    \"internal/version\",\r\n    \"pubsub\",\r\n    \"pubsub/apiv1\",\r\n    \"pubsub/internal/distribution\"\r\n  ]\r\n  revision = \"056a55f54a6cc77b440b31a56a5e7c3982d32811\"\r\n  version = \"v0.22.0\"\r\n```\r\n\r\nJust to enusre you, that this is not a mistake on our part (e.g. cancelling the context). We are using pubsub client in our wrapper, which looks like this:\r\n```\r\nfunc (r *receiver) Start(ctx context.Context) error {\r\n\tif err := r.state.Start(); err != nil {\r\n\t\treturn errors.Wrapf(err, \"failed to start receiver\")\r\n\t}\r\n\tcancelCtx, cancel := context.WithCancel(ctx)\r\n\r\n\tgo func() {\r\n\t\tr.state.WaitForClose()\r\n\t\tr.log.Infof(\"Receiver will be stopped\")\r\n\t\tcancel()\r\n\t}()\r\n\tr.subscription.ReceiveSettings.MaxOutstandingBytes = 1e6 * 10 // 20 Mi\r\n\terr := r.subscription.Receive(cancelCtx, r.receive)\r\n\r\n\tlog := r.log.WithFields(logrus.Fields{\r\n\t\t\"parent_context\":   ctx.Err(),\r\n\t\t\"receiver_context\": cancelCtx.Err(),\r\n\t\t\"error\":            err,\r\n\t\t\"close_called\":     r.state.IsClosed(),\r\n\t})\r\n\r\n\tif err != nil {\r\n\t\tlog.Infof(\"Receiver exited with error: '%v'\", err)\r\n\t} else {\r\n\t\tlog.Infof(\"Receiver exited\")\r\n\t}\r\n\r\n\tr.state.MarkAsDone()\r\n\treturn err\r\n}\r\n```\r\nWhen `Receive` exists without an error we are observing logs like: \r\n```\r\n018-07-11 15:44:26.000 CEST Receiver exited {\r\n insertId:  \"5ac6hwg1xi03vt\"  \r\n jsonPayload: {\r\n  close_called:  false   \r\n  env:  \"stage\"   \r\n  error:  null   \r\n  message:  \"Receiver exited\"   \r\n  parent_context:  null   \r\n  receiver_context:  null   \r\n  timestamp:  \"2018-07-11T13:44:26.694911319Z\"   \r\n }\r\n labels: {…}  \r\n logName:  \"projects/ingrid-head/logs/service-popular-pickuppoint\"  \r\n receiveTimestamp:  \"2018-07-11T13:44:31.407873607Z\"  \r\n resource: {…}  \r\n severity:  \"INFO\"  \r\n timestamp:  \"2018-07-11T13:44:26Z\"  \r\n}\r\n```\r\n\r\n"}}
{"actor":{"display_login":"krzysztofdrys"}}