pubsub-0.35.0.log

2018-05-29 13:57:13,687 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.dispatcher:59] Started helper thread Thread-CallbackRequestDispatcher
2018-05-29 13:57:13,687 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.bidi:484] Started helper thread Thread-ConsumeBidirectionalStream
2018-05-29 13:57:13,688 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:57:13,689 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 4.632272 seconds.
2018-05-29 13:57:13,689 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:178] Started helper thread Thread-LeaseMaintainer
2018-05-29 13:57:13,690 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.bidi:456] waiting for recv.
2018-05-29 13:57:13,793 DEBUG    [google.auth.transport.requests:117] Making request: POST https://accounts.google.com/o/oauth2/token
2018-05-29 13:57:13,796 DEBUG    [urllib3.connectionpool:824] Starting new HTTPS connection (1): accounts.google.com
2018-05-29 13:57:13,970 DEBUG    [urllib3.connectionpool:396] https://accounts.google.com:443 "POST /o/oauth2/token HTTP/1.1" 200 None
2018-05-29 13:57:17,204 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.bidi:458] recved response.
2018-05-29 13:57:17,204 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager:382] Scheduling callbacks for 5 messages.
2018-05-29 13:57:17,382 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager:256] Sent request(s) over unary RPC.
2018-05-29 13:57:17,382 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.dispatcher:91] Handling 2 batched requests
2018-05-29 13:57:17,386 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.bidi:456] waiting for recv.
2018-05-29 13:57:17,393 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.dispatcher:91] Handling 3 batched requests
2018-05-29 13:57:17,884 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.dispatcher:91] Handling 1 batched requests
2018-05-29 13:57:17,938 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager:256] Sent request(s) over unary RPC.
2018-05-29 13:57:17,948 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.dispatcher:91] Handling 4 batched requests
2018-05-29 13:57:18,054 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager:256] Sent request(s) over unary RPC.
2018-05-29 13:57:18,323 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:57:18,323 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 8.941387 seconds.
2018-05-29 13:57:27,265 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:57:27,265 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 5.757957 seconds.
2018-05-29 13:57:33,023 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:57:33,024 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 2.601188 seconds.
2018-05-29 13:57:35,626 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:57:35,626 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 8.224260 seconds.
2018-05-29 13:57:43,851 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:57:43,851 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 1.363084 seconds.
2018-05-29 13:57:45,215 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:57:45,215 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 2.951258 seconds.
2018-05-29 13:57:48,167 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:57:48,167 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 8.184837 seconds.
2018-05-29 13:57:56,352 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:57:56,352 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 5.893176 seconds.
2018-05-29 13:58:02,246 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:02,246 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 8.901380 seconds.
2018-05-29 13:58:11,149 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:11,149 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 0.152193 seconds.
2018-05-29 13:58:11,302 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:11,302 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 0.487999 seconds.
2018-05-29 13:58:11,791 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:11,791 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 8.477919 seconds.
2018-05-29 13:58:20,270 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:20,270 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 7.460728 seconds.
2018-05-29 13:58:27,732 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:27,732 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 2.105784 seconds.
2018-05-29 13:58:29,839 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:29,839 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 6.098510 seconds.
2018-05-29 13:58:35,939 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:35,939 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 7.309477 seconds.
2018-05-29 13:58:36,989 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.bidi:110] Empty queue and inactive call, exiting request generator.
2018-05-29 13:58:43,249 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:43,249 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 3.435361 seconds.
2018-05-29 13:58:46,685 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:46,686 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 0.181357 seconds.
2018-05-29 13:58:46,868 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:46,868 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 8.346021 seconds.
2018-05-29 13:58:55,215 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:55,215 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 0.647957 seconds.
2018-05-29 13:58:55,864 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:58:55,865 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 8.918429 seconds.
2018-05-29 13:59:04,784 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:59:04,784 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 0.780209 seconds.
2018-05-29 13:59:05,566 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:59:05,566 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 3.019969 seconds.
2018-05-29 13:59:08,587 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:59:08,587 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 6.928446 seconds.
2018-05-29 13:59:15,516 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:59:15,516 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 8.879507 seconds.
2018-05-29 13:59:24,397 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:59:24,397 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 6.019368 seconds.
2018-05-29 13:59:30,418 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:59:30,418 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 6.325284 seconds.
2018-05-29 13:59:36,744 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:59:36,745 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 6.637254 seconds.
2018-05-29 13:59:43,382 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:59:43,382 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 0.883945 seconds.
2018-05-29 13:59:44,267 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:59:44,267 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 2.089294 seconds.
2018-05-29 13:59:46,357 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:59:46,358 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 5.943135 seconds.
2018-05-29 13:59:52,302 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:108] The current p99 value is 10 seconds.
2018-05-29 13:59:52,302 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.leaser:161] Snoozing lease management for 3.072115 seconds.
2018-05-29 13:59:54,203 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.bidi:466] Thread-ConsumeBidirectionalStream caught error 503 The service was unable to fulfill your request. Please try again. [code=8a75] and will exit. Generally this is due to the RPC itself being cancelled and the error will be surfaced to the calling code.
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 76, in next
    return six.next(self._wrapped)
  File "/usr/local/lib/python3.6/site-packages/grpc/_channel.py", line 347, in __next__
    return self._next()
  File "/usr/local/lib/python3.6/site-packages/grpc/_channel.py", line 341, in _next
    raise self
grpc._channel._Rendezvous: <_Rendezvous of RPC that terminated with (StatusCode.UNAVAILABLE, The service was unable to fulfill your request. Please try again. [code=8a75])>

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/bidi.py", line 366, in _recoverable
    return method(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/bidi.py", line 258, in recv
    return next(self.call)
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 78, in next
    six.raise_from(exceptions.from_grpc_error(exc), exc)
  File "<string>", line 3, in raise_from
google.api_core.exceptions.ServiceUnavailable: 503 The service was unable to fulfill your request. Please try again. [code=8a75]

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 76, in next
    return six.next(self._wrapped)
  File "/usr/local/lib/python3.6/site-packages/grpc/_channel.py", line 347, in __next__
    return self._next()
  File "/usr/local/lib/python3.6/site-packages/grpc/_channel.py", line 341, in _next
    raise self
grpc._channel._Rendezvous: <_Rendezvous of RPC that terminated with (StatusCode.UNAVAILABLE, The service was unable to fulfill your request. Please try again. [code=8a75])>

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/bidi.py", line 457, in _thread_main
    response = self._bidi_rpc.recv()
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/bidi.py", line 383, in recv
    super(ResumableBidiRpc, self).recv)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/bidi.py", line 375, in _recoverable
    return method(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/bidi.py", line 258, in recv
    return next(self.call)
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 78, in next
    six.raise_from(exceptions.from_grpc_error(exc), exc)
  File "<string>", line 3, in raise_from
google.api_core.exceptions.ServiceUnavailable: 503 The service was unable to fulfill your request. Please try again. [code=8a75]
2018-05-29 13:59:54,204 INFO     [google.cloud.pubsub_v1.subscriber._protocol.bidi:473] Thread-ConsumeBidirectionalStream exiting
2018-05-29 13:59:55,091 DEBUG    [google.cloud.pubsub_v1.subscriber._protocol.bidi:110] Empty queue and inactive call, exiting request generator.
2018-05-29 13:59:55,375 INFO     [google.cloud.pubsub_v1.subscriber._protocol.leaser:164] Thread-LeaseMaintainer exiting.