Repro for https://github.com/GoogleCloudPlatform/google-cloud-python/issues/4234

fail_4234.py

import argparse
import logging
import threading
import time

import google.auth
import grpc._channel
import grpc._common
import six

from google.cloud.pubsub_v1.subscriber.policy import base
from google.cloud import pubsub_v1


_, PROJECT = google.auth.default()
# NOTE: Must set the logging level on the "root" logger since
#       the orchestration across threads is funky (I still do
#       not **fully** understand it).
logging.getLogger().setLevel(logging.DEBUG)
LOGGER_NAME = 'REPRO.4234'
LOGGER = logging.getLogger(LOGGER_NAME)
FORMAT = (
    'timeLevel=%(relativeCreated)08d:%(levelname)s\n'
    'logger=%(name)s\n'
    'threadName=%(threadName)s\n'
    '%(message)s\n'
    '----------------------------------------')
logging.basicConfig(format=FORMAT)

# Monkey-patch to intentionally miss errors.
base.BasePolicy._RETRYABLE_STREAM_ERRORS = ()

ORIGINAL_THREAD = threading.Thread
ORIGINAL_CLEANUP_THREAD_CONSTRUCTOR = grpc._common.CleanupThread.__init__
PLUGIN_GET_METADATA_REPR = (
    '<cyfunction plugin_get_metadata.<locals>.async_callback at 0x')
CHANNEL_SPIN_REPR = (
    '<function _run_channel_spin_thread.<locals>.channel_spin at 0x')
CONSUME_REQUEST_REPR = (
    '<function _consume_request_iterator.<locals>.'
    'consume_request_iterator at 0x')


def update_thread_kwargs(args, kwargs):
    if 'name' in kwargs:
        return

    if 'target' not in kwargs:
        raise KeyError(
            'Thread has no name or target', args, kwargs)

    target = kwargs['target']

    # Expected case 1: Spawned in ``grpc._channel._spawn_delivery()``.
    if target is grpc._channel._deliver:
        kwargs['name'] = 'Thread-gRPC-SpawnDelivery'
        return

    # Expected case 2: Spawned in ``grpc._channel._subscribe()``.
    if target is grpc._channel._poll_connectivity:
        kwargs['name'] = 'Thread-gRPC-SubscribeMoot'
        return

    # Expected case 3: Spawned in ``plugin_get_metadata()`` in the Cython
    # file ``grpc/_cython/_cygrpc/credentials.pyx.pxi``.
    target_repr = repr(target)
    if target_repr.startswith(PLUGIN_GET_METADATA_REPR):
        kwargs['name'] = 'Thread-gRPC-PluginGetMetadata'
        return

    # Expected case 4: Spawned in ``grpc._channel._run_channel_spin_thread()``.
    if target_repr.startswith(CHANNEL_SPIN_REPR):
        kwargs['name'] = 'Thread-gRPC-StopChannelSpin'
        return

    # Expected case 5: Spawned in
    # ``grpc._channel._consume_request_iterator()``.
    if target_repr.startswith(CONSUME_REQUEST_REPR):
        kwargs['name'] = 'Thread-gRPC-ConsumeRequestIterator'
        return

    # Expected case 6: From ``google-cloud-pubsub==0.29.0``.
    func = getattr(target, '__func__', None)
    if func is base.BasePolicy.maintain_leases:
        kwargs['name'] = 'Thread-LeaseMaintenance'
        return

    # Expected case 7: From ``google-cloud-pubsub==0.29.0``.
    if func is pubsub_v1.publisher.batch.thread.Batch.monitor:
        kwargs['name'] = 'Thread-MonitorBatchPublisher'
        return

    raise TypeError(
        'Unexpected target', args, kwargs)


def named_thread(*args, **kwargs):
    update_thread_kwargs(args, kwargs)
    return ORIGINAL_THREAD(*args, **kwargs)


def named_cleanup_thread_constructor(self, behavior, *args, **kwargs):
    update_thread_kwargs(args, kwargs)
    ORIGINAL_THREAD.__init__(self, *args, **kwargs)
    self._behavior = behavior


def unique_resource_id(prefix):
    return '{}-djh-local-{}'.format(prefix, int(1000 * time.time()))


def info(published, data):
    data = data.decode('utf-8')
    if published:
        msg = 'Published: {}'.format(data)
    else:
        msg = ' Received: {}'.format(data)
    LOGGER.info(msg)


def ack_callback(message):
    info(False, message.data)
    message.ack()


def get_topic_path(publisher):
    topic_name = unique_resource_id('t')
    return publisher.topic_path(PROJECT, topic_name)


def get_subscription_path(subscriber):
    sub_name = unique_resource_id('s')
    return subscriber.subscription_path(PROJECT, sub_name)


def publish(count, interval, publisher, topic_path):
    for index in six.moves.range(count):
        data = u'Wooooo! The claaaaaw! (index={})'.format(index)
        data = data.encode('utf-8')
        publisher.publish(
            topic_path,
            data,
        )
        info(True, data)
        time.sleep(interval)


def get_flag():
    parser = argparse.ArgumentParser(
        description='Run example showcasing Pub / Sub failures.')
    parser.add_argument(
        '--do-not-create',
        dest='do_not_create',
        action='store_true',
        help='Indicates if the subscription should be created.',
    )
    args = parser.parse_args()
    return not args.do_not_create


def main():
    do_create = get_flag()

    # First monkey-patch ``threading.Thread`` and
    # ``grpc._common.CleanupThread``.
    threading.Thread = named_thread
    grpc._common.CleanupThread.__init__ = named_cleanup_thread_constructor

    publisher = pubsub_v1.PublisherClient()
    topic_path = get_topic_path(publisher)
    subscriber = pubsub_v1.SubscriberClient()
    subscription_path = get_subscription_path(subscriber)

    # Create a topic.
    publisher.create_topic(topic_path)

    # Subscribe to the topic. This must happen before the messages
    # are published.
    if do_create:
        subscriber.create_subscription(subscription_path, topic_path)
    subscription = subscriber.subscribe(subscription_path)

    # Set off async job to publish some messages.
    thread = threading.Thread(
        target=publish,
        args=(5, 3, publisher, topic_path),
        name='Thread-ReproPublish',
    )
    thread.start()

    # Actually open the subscription and hold it open.
    sub_future = subscription.open(ack_callback)
    consumer = sub_future._policy._consumer

    # The subscriber is non-blocking, so we must keep the main thread from
    # exiting to allow it to process messages in the background.
    msg = 'Listening for messages on {}'.format(subscription_path)
    LOGGER.info(msg)
    done_count = 0
    while True:
        is_running = sub_future.running()
        is_done = sub_future.done()
        LOGGER.info(
            'sub.open() future (running=%s, done=%s)',
            is_running,
            is_done,
        )
        time.sleep(10)
        done_count += int(is_done)
        if is_done and not consumer.active and done_count > 3:
            LOGGER.info(
                'sub.open() future exception:\n%s', sub_future._exception)
            LOGGER.info(
                'sub.open() future completed.is_set()? %s',
                sub_future._completed.is_set())
            break

    # Do clean-up.
    publisher.delete_topic(topic_path)
    if do_create:
        subscriber.delete_subscription(subscription_path)

    # Put back the real ``Thread`` classes before exit.
    threading.Thread = ORIGINAL_THREAD
    grpc._common.CleanupThread.__init__ = ORIGINAL_CLEANUP_THREAD_CONSTRUCTOR


if __name__ == '__main__':
    main()

logs_local.txt

$ git log -1 --pretty=%H
49285a340a92110f2c9371e3a3b638e948206653
$
$ python -m virtualenv venv-local
$ venv-local/bin/python -m pip install pubsub/
$ venv-local/bin/python -m pip show google-cloud-pubsub
Name: google-cloud-pubsub
Version: 0.29.2.dev1
...
$
$ venv-local/bin/python fail_4234.py
timeLevel=00000503:DEBUG
logger=google.auth.transport.requests
threadName=Thread-gRPC-PluginGetMetadata
Making request: POST https://accounts.google.com/o/oauth2/token
----------------------------------------
timeLevel=00000507:DEBUG
logger=urllib3.connectionpool
threadName=Thread-gRPC-PluginGetMetadata
Starting new HTTPS connection (1): accounts.google.com
----------------------------------------
timeLevel=00000702:DEBUG
logger=urllib3.connectionpool
threadName=Thread-gRPC-PluginGetMetadata
https://accounts.google.com:443 "POST /o/oauth2/token HTTP/1.1" 200 None
----------------------------------------
timeLevel=00002057:DEBUG
logger=google.auth.transport.requests
threadName=Thread-gRPC-PluginGetMetadata
Making request: POST https://accounts.google.com/o/oauth2/token
----------------------------------------
timeLevel=00002059:DEBUG
logger=urllib3.connectionpool
threadName=Thread-gRPC-PluginGetMetadata
Starting new HTTPS connection (1): accounts.google.com
----------------------------------------
timeLevel=00002221:DEBUG
logger=urllib3.connectionpool
threadName=Thread-gRPC-PluginGetMetadata
https://accounts.google.com:443 "POST /o/oauth2/token HTTP/1.1" 200 None
----------------------------------------
timeLevel=00004072:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=MainThread
Creating callback requests thread (not starting).
----------------------------------------
timeLevel=00004074:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=MainThread
Starting callback requests worker.
----------------------------------------
timeLevel=00004074:DEBUG
logger=google.cloud.pubsub_v1.subscriber._helper_threads
threadName=MainThread
Started helper thread CallbackRequestsWorker
----------------------------------------
timeLevel=00004075:INFO
logger=REPRO.4234
threadName=Thread-ReproPublish
Published: Wooooo! The claaaaaw! (index=0)
----------------------------------------
timeLevel=00004076:DEBUG
logger=google.cloud.pubsub_v1.subscriber._helper_threads
threadName=MainThread
Started helper thread ConsumeBidirectionalStream
----------------------------------------
timeLevel=00004076:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=MainThread
Spawning lease maintenance worker.
----------------------------------------
timeLevel=00004077:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00004078:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00004079:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 3.319658 seconds.
----------------------------------------
timeLevel=00004081:INFO
logger=REPRO.4234
threadName=MainThread
Listening for messages on projects/precise-truck-742/subscriptions/s-djh-local-1511932513110
----------------------------------------
timeLevel=00004081:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00004082:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending initial request:
subscription: "projects/precise-truck-742/subscriptions/s-djh-local-1511932513110"
stream_ack_deadline_seconds: 10

----------------------------------------
timeLevel=00004408:DEBUG
logger=google.cloud.pubsub_v1.publisher.batch.thread
threadName=Thread-MonitorBatchPublisher
gRPC Publish took 0.28379082679748535 seconds.
----------------------------------------
timeLevel=00006140:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
Received response:
received_messages {
  ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJZGGJoXFx1B1ALGXJ7YnZvCBsFCEVZfndrOTJpW1pxBlAKH3Z4aXNoWhIp-PCSqOlgZh89WxJLLD4"
  message {
    data: "Wooooo! The claaaaaw! (index=0)"
    message_id: "176411764586201"
    publish_time {
      seconds: 1511932517
      nanos: 258000000
    }
  }
}

----------------------------------------
timeLevel=00006141:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
New message received from Pub/Sub:
ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJZGGJoXFx1B1ALGXJ7YnZvCBsFCEVZfndrOTJpW1pxBlAKH3Z4aXNoWhIp-PCSqOlgZh89WxJLLD4"
message {
  data: "Wooooo! The claaaaaw! (index=0)"
  message_id: "176411764586201"
  publish_time {
    seconds: 1511932517
    nanos: 258000000
  }
}

----------------------------------------
timeLevel=00006141:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
<function ack_callback at 0x7fa6b99c17b8>
----------------------------------------
timeLevel=00006142:INFO
logger=REPRO.4234
threadName=ThreadPoolExecutor-0_0
 Received: Wooooo! The claaaaaw! (index=0)
----------------------------------------
timeLevel=00006142:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
Result: None
----------------------------------------
timeLevel=00006144:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending request:
ack_ids: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJZGGJoXFx1B1ALGXJ7YnZvCBsFCEVZfndrOTJpW1pxBlAKH3Z4aXNoWhIp-PCSqOlgZh89WxJLLD4"

----------------------------------------
timeLevel=00007079:INFO
logger=REPRO.4234
threadName=Thread-ReproPublish
Published: Wooooo! The claaaaaw! (index=1)
----------------------------------------
timeLevel=00007237:DEBUG
logger=google.cloud.pubsub_v1.publisher.batch.thread
threadName=Thread-MonitorBatchPublisher
gRPC Publish took 0.10790753364562988 seconds.
----------------------------------------
timeLevel=00007239:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
Received response:
received_messages {
  ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJZGGJoXFx1B1ALGXJ7YnZvCBsFCERZfndrOTJpW1pxAVIOEXJ8Y31vUhQp-PCSqOlgZh89WxJLLD4"
  message {
    data: "Wooooo! The claaaaaw! (index=1)"
    message_id: "176463380128587"
    publish_time {
      seconds: 1511932520
      nanos: 88000000
    }
  }
}

----------------------------------------
timeLevel=00007239:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
New message received from Pub/Sub:
ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJZGGJoXFx1B1ALGXJ7YnZvCBsFCERZfndrOTJpW1pxAVIOEXJ8Y31vUhQp-PCSqOlgZh89WxJLLD4"
message {
  data: "Wooooo! The claaaaaw! (index=1)"
  message_id: "176463380128587"
  publish_time {
    seconds: 1511932520
    nanos: 88000000
  }
}

----------------------------------------
timeLevel=00007239:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
<function ack_callback at 0x7fa6b99c17b8>
----------------------------------------
timeLevel=00007240:INFO
logger=REPRO.4234
threadName=ThreadPoolExecutor-0_1
 Received: Wooooo! The claaaaaw! (index=1)
----------------------------------------
timeLevel=00007240:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=ThreadPoolExecutor-0_1
Result: None
----------------------------------------
timeLevel=00007240:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending request:
ack_ids: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJZGGJoXFx1B1ALGXJ7YnZvCBsFCERZfndrOTJpW1pxAVIOEXJ8Y31vUhQp-PCSqOlgZh89WxJLLD4"

----------------------------------------
timeLevel=00007403:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00007403:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00007403:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.803519 seconds.
----------------------------------------
timeLevel=00009207:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00009207:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00009207:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.658089 seconds.
----------------------------------------
timeLevel=00010083:INFO
logger=REPRO.4234
threadName=Thread-ReproPublish
Published: Wooooo! The claaaaaw! (index=2)
----------------------------------------
timeLevel=00010309:DEBUG
logger=google.cloud.pubsub_v1.publisher.batch.thread
threadName=Thread-MonitorBatchPublisher
gRPC Publish took 0.176727294921875 seconds.
----------------------------------------
timeLevel=00010720:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
Received response:
received_messages {
  ack_id: "Pn41MEVBXkASTD4FRElTK0MLKlgRTgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEURACBsEyRCWXQNaFxcdQZXDRl0fmJyaF4QCwJPU1ZveSQMb1pYdwBUBR9xe2V0blo7-7eEhchkZhw9WxJLLA"
  message {
    data: "Wooooo! The claaaaaw! (index=2)"
    message_id: "176427586364140"
    publish_time {
      seconds: 1511932523
      nanos: 83000000
    }
  }
}

----------------------------------------
timeLevel=00010720:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
New message received from Pub/Sub:
ack_id: "Pn41MEVBXkASTD4FRElTK0MLKlgRTgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEURACBsEyRCWXQNaFxcdQZXDRl0fmJyaF4QCwJPU1ZveSQMb1pYdwBUBR9xe2V0blo7-7eEhchkZhw9WxJLLA"
message {
  data: "Wooooo! The claaaaaw! (index=2)"
  message_id: "176427586364140"
  publish_time {
    seconds: 1511932523
    nanos: 83000000
  }
}

----------------------------------------
timeLevel=00010720:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
<function ack_callback at 0x7fa6b99c17b8>
----------------------------------------
timeLevel=00010720:INFO
logger=REPRO.4234
threadName=ThreadPoolExecutor-0_0
 Received: Wooooo! The claaaaaw! (index=2)
----------------------------------------
timeLevel=00010721:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
Result: None
----------------------------------------
timeLevel=00010721:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending request:
ack_ids: "Pn41MEVBXkASTD4FRElTK0MLKlgRTgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEURACBsEyRCWXQNaFxcdQZXDRl0fmJyaF4QCwJPU1ZveSQMb1pYdwBUBR9xe2V0blo7-7eEhchkZhw9WxJLLA"

----------------------------------------
timeLevel=00013087:INFO
logger=REPRO.4234
threadName=Thread-ReproPublish
Published: Wooooo! The claaaaaw! (index=3)
----------------------------------------
timeLevel=00013336:DEBUG
logger=google.cloud.pubsub_v1.publisher.batch.thread
threadName=Thread-MonitorBatchPublisher
gRPC Publish took 0.19997715950012207 seconds.
----------------------------------------
timeLevel=00013718:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
Received response:
received_messages {
  ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJaHGJoXFx1B1ALGXJ7YnZtDkVUCEVZfndrOTJpW1pxBFkLHHB_Y3xuUxYp-PCSqOlgZh89WxJLLD4"
  message {
    data: "Wooooo! The claaaaaw! (index=3)"
    message_id: "176438652229495"
    publish_time {
      seconds: 1511932526
      nanos: 86000000
    }
  }
}

----------------------------------------
timeLevel=00013718:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
New message received from Pub/Sub:
ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJaHGJoXFx1B1ALGXJ7YnZtDkVUCEVZfndrOTJpW1pxBFkLHHB_Y3xuUxYp-PCSqOlgZh89WxJLLD4"
message {
  data: "Wooooo! The claaaaaw! (index=3)"
  message_id: "176438652229495"
  publish_time {
    seconds: 1511932526
    nanos: 86000000
  }
}

----------------------------------------
timeLevel=00013718:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
<function ack_callback at 0x7fa6b99c17b8>
----------------------------------------
timeLevel=00013719:INFO
logger=REPRO.4234
threadName=ThreadPoolExecutor-0_1
 Received: Wooooo! The claaaaaw! (index=3)
----------------------------------------
timeLevel=00013719:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
Result: None
----------------------------------------
timeLevel=00013719:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending request:
ack_ids: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJaHGJoXFx1B1ALGXJ7YnZtDkVUCEVZfndrOTJpW1pxBFkLHHB_Y3xuUxYp-PCSqOlgZh89WxJLLD4"

----------------------------------------
timeLevel=00014086:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00015871:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00015871:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00015871:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 5.021424 seconds.
----------------------------------------
timeLevel=00016090:INFO
logger=REPRO.4234
threadName=Thread-ReproPublish
Published: Wooooo! The claaaaaw! (index=4)
----------------------------------------
timeLevel=00016225:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
Received response:
received_messages {
  ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJZGGJoXFx1B1ALGXJ7YnZvCBsFCEdZfndrOTJpW1pxBFIJGnV-YHVvWRMp-PCSqOlgZh89WxJLLD4"
  message {
    data: "Wooooo! The claaaaaw! (index=4)"
    message_id: "176433437310530"
    publish_time {
      seconds: 1511932529
      nanos: 78000000
    }
  }
}

----------------------------------------
timeLevel=00016225:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
New message received from Pub/Sub:
ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJZGGJoXFx1B1ALGXJ7YnZvCBsFCEdZfndrOTJpW1pxBFIJGnV-YHVvWRMp-PCSqOlgZh89WxJLLD4"
message {
  data: "Wooooo! The claaaaaw! (index=4)"
  message_id: "176433437310530"
  publish_time {
    seconds: 1511932529
    nanos: 78000000
  }
}

----------------------------------------
timeLevel=00016225:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Thread-ConsumerHelper-ConsumeBidirectionalStream
<function ack_callback at 0x7fa6b99c17b8>
----------------------------------------
timeLevel=00016226:INFO
logger=REPRO.4234
threadName=ThreadPoolExecutor-0_4
 Received: Wooooo! The claaaaaw! (index=4)
----------------------------------------
timeLevel=00016226:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=ThreadPoolExecutor-0_4
Result: None
----------------------------------------
timeLevel=00016226:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending request:
ack_ids: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRREAIG8TJEJZGGJoXFx1B1ALGXJ7YnZvCBsFCEdZfndrOTJpW1pxBFIJGnV-YHVvWRMp-PCSqOlgZh89WxJLLD4"

----------------------------------------
timeLevel=00016229:DEBUG
logger=google.cloud.pubsub_v1.publisher.batch.thread
threadName=Thread-MonitorBatchPublisher
gRPC Publish took 0.08846783638000488 seconds.
----------------------------------------
timeLevel=00020895:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00020895:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00020895:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.513559 seconds.
----------------------------------------
timeLevel=00022411:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00022411:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00022411:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.102184 seconds.
----------------------------------------
timeLevel=00023513:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00023514:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00023514:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 8.542629 seconds.
----------------------------------------
timeLevel=00024097:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00032063:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00032063:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00032064:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 4.072284 seconds.
----------------------------------------
timeLevel=00034107:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00036140:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00036140:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00036140:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.597976 seconds.
----------------------------------------
timeLevel=00042745:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00042745:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00042745:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 0.368715 seconds.
----------------------------------------
timeLevel=00043114:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00043115:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00043115:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 5.886774 seconds.
----------------------------------------
timeLevel=00044117:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00049005:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00049005:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00049006:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 8.721596 seconds.
----------------------------------------
timeLevel=00054127:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00057735:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00057735:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00057735:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.525020 seconds.
----------------------------------------
timeLevel=00064137:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00064267:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00064267:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00064267:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 5.074180 seconds.
----------------------------------------
timeLevel=00069346:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00069347:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00069347:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 2.610200 seconds.
----------------------------------------
timeLevel=00071960:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00071960:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00071960:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 7.446807 seconds.
----------------------------------------
timeLevel=00074147:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00079415:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00079415:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00079416:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 2.351628 seconds.
----------------------------------------
timeLevel=00081770:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00081770:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00081770:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.705845 seconds.
----------------------------------------
timeLevel=00084158:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00088483:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00088483:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00088483:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 3.654305 seconds.
----------------------------------------
timeLevel=00092139:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00092140:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00092140:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.701939 seconds.
----------------------------------------
timeLevel=00094168:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00098846:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00098846:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00098846:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.785830 seconds.
----------------------------------------
timeLevel=00104179:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00105639:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00105639:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00105639:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.158377 seconds.
----------------------------------------
timeLevel=00111804:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00111804:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00111804:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.575563 seconds.
----------------------------------------
timeLevel=00114189:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00118385:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00118385:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00118385:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.012939 seconds.
----------------------------------------
timeLevel=00119400:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00119400:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00119400:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 8.725779 seconds.
----------------------------------------
timeLevel=00123011:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending initial request:
subscription: "projects/precise-truck-742/subscriptions/s-djh-local-1511932513110"
stream_ack_deadline_seconds: 10

----------------------------------------
timeLevel=00124200:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=False, done=True)
----------------------------------------
timeLevel=00134210:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=False, done=True)
----------------------------------------
timeLevel=00144221:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=False, done=True)
----------------------------------------
timeLevel=00154231:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=False, done=True)
----------------------------------------
timeLevel=00164242:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future exception:
503 The service was unable to fulfill your request. Please try again. [code=8a75]
----------------------------------------
timeLevel=00164242:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future completed.is_set()? True
----------------------------------------

logs_pypi.txt

$ python -m virtualenv venv-pypi
$ venv-pypi/bin/python -m pip install 'google-cloud-pubsub==0.29.0'
$ venv-pypi/bin/python -m pip show google-cloud-pubsub
Name: google-cloud-pubsub
Version: 0.29.0
...
$
$ venv-pypi/bin/python fail_4234.py
timeLevel=00000519:DEBUG
logger=google.auth.transport.requests
threadName=Thread-gRPC-PluginGetMetadata
Making request: POST https://accounts.google.com/o/oauth2/token
----------------------------------------
timeLevel=00000521:DEBUG
logger=urllib3.connectionpool
threadName=Thread-gRPC-PluginGetMetadata
Starting new HTTPS connection (1): accounts.google.com
----------------------------------------
timeLevel=00000721:DEBUG
logger=urllib3.connectionpool
threadName=Thread-gRPC-PluginGetMetadata
https://accounts.google.com:443 "POST /o/oauth2/token HTTP/1.1" 200 None
----------------------------------------
timeLevel=00001743:DEBUG
logger=google.auth.transport.requests
threadName=Thread-gRPC-PluginGetMetadata
Making request: POST https://accounts.google.com/o/oauth2/token
----------------------------------------
timeLevel=00001745:DEBUG
logger=urllib3.connectionpool
threadName=Thread-gRPC-PluginGetMetadata
Starting new HTTPS connection (1): accounts.google.com
----------------------------------------
timeLevel=00001904:DEBUG
logger=urllib3.connectionpool
threadName=Thread-gRPC-PluginGetMetadata
https://accounts.google.com:443 "POST /o/oauth2/token HTTP/1.1" 200 None
----------------------------------------
timeLevel=00003630:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=MainThread
Creating callback requests thread (not starting).
----------------------------------------
timeLevel=00003631:INFO
logger=REPRO.4234
threadName=Thread-ReproPublish
Published: Wooooo! The claaaaaw! (index=0)
----------------------------------------
timeLevel=00003631:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=MainThread
Starting callback requests worker.
----------------------------------------
timeLevel=00003632:DEBUG
logger=google.cloud.pubsub_v1.subscriber._helper_threads
threadName=MainThread
Started helper thread callback requests worker
----------------------------------------
timeLevel=00003633:DEBUG
logger=google.cloud.pubsub_v1.subscriber._helper_threads
threadName=MainThread
Started helper thread consume bidirectional stream
----------------------------------------
timeLevel=00003633:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=MainThread
Spawning lease maintenance worker.
----------------------------------------
timeLevel=00003634:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00003635:INFO
logger=REPRO.4234
threadName=MainThread
Listening for messages on projects/precise-truck-742/subscriptions/s-djh-local-1511933732759
----------------------------------------
timeLevel=00003635:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00003636:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending initial request: subscription: "projects/precise-truck-742/subscriptions/s-djh-local-1511933732759"
stream_ack_deadline_seconds: 10

----------------------------------------
timeLevel=00003636:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00003637:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 4.703237 seconds.
----------------------------------------
timeLevel=00003936:DEBUG
logger=root
threadName=Thread-MonitorBatchPublisher
gRPC Publish took 0.25468897819519043 seconds.
----------------------------------------
timeLevel=00005061:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Consumer helper: consume bidirectional stream
Received response: received_messages {
  ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRRIBIG8TJEJaG2JoXFx1B1ALGXJ7ZXA8X0BUCEVZfndrOTJpW1pxBFkLGXN7aXZpWBMpovzYyOhgZh89WxJLLD4"
  message {
    data: "Wooooo! The claaaaaw! (index=0)"
    message_id: "176438601683320"
    publish_time {
      seconds: 1511933736
      nanos: 406000000
    }
  }
}

----------------------------------------
timeLevel=00005061:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
New message received from Pub/Sub: ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRRIBIG8TJEJaG2JoXFx1B1ALGXJ7ZXA8X0BUCEVZfndrOTJpW1pxBFkLGXN7aXZpWBMpovzYyOhgZh89WxJLLD4"
message {
  data: "Wooooo! The claaaaaw! (index=0)"
  message_id: "176438601683320"
  publish_time {
    seconds: 1511933736
    nanos: 406000000
  }
}

----------------------------------------
timeLevel=00005062:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
<function ack_callback at 0x7fb905dbd158>
----------------------------------------
timeLevel=00005063:INFO
logger=REPRO.4234
threadName=ThreadPoolExecutor-0_0
 Received: Wooooo! The claaaaaw! (index=0)
----------------------------------------
timeLevel=00005063:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending request: ack_ids: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRRIBIG8TJEJaG2JoXFx1B1ALGXJ7ZXA8X0BUCEVZfndrOTJpW1pxBFkLGXN7aXZpWBMpovzYyOhgZh89WxJLLD4"

----------------------------------------
timeLevel=00005064:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
Result: None
----------------------------------------
timeLevel=00006635:INFO
logger=REPRO.4234
threadName=Thread-ReproPublish
Published: Wooooo! The claaaaaw! (index=1)
----------------------------------------
timeLevel=00006761:DEBUG
logger=root
threadName=Thread-MonitorBatchPublisher
gRPC Publish took 0.07570052146911621 seconds.
----------------------------------------
timeLevel=00007310:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Consumer helper: consume bidirectional stream
Received response: received_messages {
  ack_id: "Pn41MEVBXkASTD4FRElTK0MLKlgRTgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEUSASBsEyRCXnQNaFxcdQZXDRl0eWd1agwUCwJPU1ZveSQMb1pYdgNZDxlyfml9bVk7obvO5clkZhw9WxJLLA"
  message {
    data: "Wooooo! The claaaaaw! (index=1)"
    message_id: "176434820038873"
    publish_time {
      seconds: 1511933739
      nanos: 262000000
    }
  }
}

----------------------------------------
timeLevel=00007310:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
New message received from Pub/Sub: ack_id: "Pn41MEVBXkASTD4FRElTK0MLKlgRTgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEUSASBsEyRCXnQNaFxcdQZXDRl0eWd1agwUCwJPU1ZveSQMb1pYdgNZDxlyfml9bVk7obvO5clkZhw9WxJLLA"
message {
  data: "Wooooo! The claaaaaw! (index=1)"
  message_id: "176434820038873"
  publish_time {
    seconds: 1511933739
    nanos: 262000000
  }
}

----------------------------------------
timeLevel=00007311:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
<function ack_callback at 0x7fb905dbd158>
----------------------------------------
timeLevel=00007311:INFO
logger=REPRO.4234
threadName=ThreadPoolExecutor-0_0
 Received: Wooooo! The claaaaaw! (index=1)
----------------------------------------
timeLevel=00007312:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=ThreadPoolExecutor-0_0
Result: None
----------------------------------------
timeLevel=00007313:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending request: ack_ids: "Pn41MEVBXkASTD4FRElTK0MLKlgRTgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEUSASBsEyRCXnQNaFxcdQZXDRl0eWd1agwUCwJPU1ZveSQMb1pYdgNZDxlyfml9bVk7obvO5clkZhw9WxJLLA"

----------------------------------------
timeLevel=00008346:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00008346:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00008347:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 3.958462 seconds.
----------------------------------------
timeLevel=00009639:INFO
logger=REPRO.4234
threadName=Thread-ReproPublish
Published: Wooooo! The claaaaaw! (index=2)
----------------------------------------
timeLevel=00009762:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Consumer helper: consume bidirectional stream
Received response: received_messages {
  ack_id: "Pn41MEVBXkASTD4FRElTK0MLKlgRTgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEUSASBsEyRCXnQNaFxcdQZXDRl0eWd1agwUCwNPU1ZveSQMb1pYdAZWDRx1fWFzaFs7obvO5clkZhw9WxJLLA"
  message {
    data: "Wooooo! The claaaaaw! (index=2)"
    message_id: "176411705700621"
    publish_time {
      seconds: 1511933742
      nanos: 266000000
    }
  }
}

----------------------------------------
timeLevel=00009762:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
New message received from Pub/Sub: ack_id: "Pn41MEVBXkASTD4FRElTK0MLKlgRTgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEUSASBsEyRCXnQNaFxcdQZXDRl0eWd1agwUCwNPU1ZveSQMb1pYdAZWDRx1fWFzaFs7obvO5clkZhw9WxJLLA"
message {
  data: "Wooooo! The claaaaaw! (index=2)"
  message_id: "176411705700621"
  publish_time {
    seconds: 1511933742
    nanos: 266000000
  }
}

----------------------------------------
timeLevel=00009762:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
<function ack_callback at 0x7fb905dbd158>
----------------------------------------
timeLevel=00009763:INFO
logger=REPRO.4234
threadName=ThreadPoolExecutor-0_1
 Received: Wooooo! The claaaaaw! (index=2)
----------------------------------------
timeLevel=00009764:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending request: ack_ids: "Pn41MEVBXkASTD4FRElTK0MLKlgRTgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEUSASBsEyRCXnQNaFxcdQZXDRl0eWd1agwUCwNPU1ZveSQMb1pYdAZWDRx1fWFzaFs7obvO5clkZhw9WxJLLA"

----------------------------------------
timeLevel=00009764:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
Result: None
----------------------------------------
timeLevel=00009765:DEBUG
logger=root
threadName=Thread-MonitorBatchPublisher
gRPC Publish took 0.07593750953674316 seconds.
----------------------------------------
timeLevel=00012309:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00012310:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00012310:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 4.026099 seconds.
----------------------------------------
timeLevel=00012643:INFO
logger=REPRO.4234
threadName=Thread-ReproPublish
Published: Wooooo! The claaaaaw! (index=3)
----------------------------------------
timeLevel=00012751:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Consumer helper: consume bidirectional stream
Received response: received_messages {
  ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRRIBIG8TJEJaG2JoXFx1B1ALGXJ7ZXA8X0BUCERZfndrOTJpW1pxA1IEGHp8aHZvWRIpovzYyOhgZh89WxJLLD4"
  message {
    data: "Wooooo! The claaaaaw! (index=3)"
    message_id: "176443918193531"
    publish_time {
      seconds: 1511933745
      nanos: 256000000
    }
  }
}

----------------------------------------
timeLevel=00012751:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
New message received from Pub/Sub: ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRRIBIG8TJEJaG2JoXFx1B1ALGXJ7ZXA8X0BUCERZfndrOTJpW1pxA1IEGHp8aHZvWRIpovzYyOhgZh89WxJLLD4"
message {
  data: "Wooooo! The claaaaaw! (index=3)"
  message_id: "176443918193531"
  publish_time {
    seconds: 1511933745
    nanos: 256000000
  }
}

----------------------------------------
timeLevel=00012751:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
<function ack_callback at 0x7fb905dbd158>
----------------------------------------
timeLevel=00012752:INFO
logger=REPRO.4234
threadName=ThreadPoolExecutor-0_0
 Received: Wooooo! The claaaaaw! (index=3)
----------------------------------------
timeLevel=00012752:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=ThreadPoolExecutor-0_0
Result: None
----------------------------------------
timeLevel=00012753:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending request: ack_ids: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRRIBIG8TJEJaG2JoXFx1B1ALGXJ7ZXA8X0BUCERZfndrOTJpW1pxA1IEGHp8aHZvWRIpovzYyOhgZh89WxJLLD4"

----------------------------------------
timeLevel=00012754:DEBUG
logger=root
threadName=Thread-MonitorBatchPublisher
gRPC Publish took 0.060656070709228516 seconds.
----------------------------------------
timeLevel=00013648:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00015647:INFO
logger=REPRO.4234
threadName=Thread-ReproPublish
Published: Wooooo! The claaaaaw! (index=4)
----------------------------------------
timeLevel=00015791:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Consumer helper: consume bidirectional stream
Received response: received_messages {
  ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRRIBIG8TJEJaG2JoXFx1B1ALGXJ7ZXA8X0BUCEdZfndrOTJpW1pxBVQOHHp7ZnRrWBspovzYyOhgZh89WxJLLD4"
  message {
    data: "Wooooo! The claaaaaw! (index=4)"
    message_id: "176425358671128"
    publish_time {
      seconds: 1511933748
      nanos: 296000000
    }
  }
}

----------------------------------------
timeLevel=00015791:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
New message received from Pub/Sub: ack_id: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRRIBIG8TJEJaG2JoXFx1B1ALGXJ7ZXA8X0BUCEdZfndrOTJpW1pxBVQOHHp7ZnRrWBspovzYyOhgZh89WxJLLD4"
message {
  data: "Wooooo! The claaaaaw! (index=4)"
  message_id: "176425358671128"
  publish_time {
    seconds: 1511933748
    nanos: 296000000
  }
}

----------------------------------------
timeLevel=00015791:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
<function ack_callback at 0x7fb905dbd158>
----------------------------------------
timeLevel=00015792:INFO
logger=REPRO.4234
threadName=ThreadPoolExecutor-0_2
 Received: Wooooo! The claaaaaw! (index=4)
----------------------------------------
timeLevel=00015792:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.thread
threadName=Consumer helper: consume bidirectional stream
Result: None
----------------------------------------
timeLevel=00015793:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending request: ack_ids: "fjUwRUFeQBJMPgVESVMrQwsqWBFOBCEhPjA-RVNEUAYWLF1GSFE3GQhoUQ5PXiM_NSAoRRIBIG8TJEJaG2JoXFx1B1ALGXJ7ZXA8X0BUCEdZfndrOTJpW1pxBVQOHHp7ZnRrWBspovzYyOhgZh89WxJLLD4"

----------------------------------------
timeLevel=00015795:DEBUG
logger=root
threadName=Thread-MonitorBatchPublisher
gRPC Publish took 0.09743189811706543 seconds.
----------------------------------------
timeLevel=00016340:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00016340:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00016341:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 0.778069 seconds.
----------------------------------------
timeLevel=00017120:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00017120:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00017120:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 5.877293 seconds.
----------------------------------------
timeLevel=00023004:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00023004:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00023004:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 0.890988 seconds.
----------------------------------------
timeLevel=00023658:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00023896:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00023896:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00023897:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.731867 seconds.
----------------------------------------
timeLevel=00025630:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00025631:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00025631:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 3.064625 seconds.
----------------------------------------
timeLevel=00028699:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00028699:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00028699:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 7.220083 seconds.
----------------------------------------
timeLevel=00033663:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00035927:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00035927:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00035927:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 4.873282 seconds.
----------------------------------------
timeLevel=00040806:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00040806:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00040806:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 8.644395 seconds.
----------------------------------------
timeLevel=00043674:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00049460:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00049460:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00049460:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.074704 seconds.
----------------------------------------
timeLevel=00050536:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00050537:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00050537:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 7.627926 seconds.
----------------------------------------
timeLevel=00053684:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00058173:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00058173:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00058173:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.020144 seconds.
----------------------------------------
timeLevel=00063694:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00064198:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00064199:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00064199:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.265574 seconds.
----------------------------------------
timeLevel=00065466:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00065466:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00065466:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.283043 seconds.
----------------------------------------
timeLevel=00071756:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00071756:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00071756:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 2.853658 seconds.
----------------------------------------
timeLevel=00073705:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00074613:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00074614:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00074614:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.532171 seconds.
----------------------------------------
timeLevel=00076148:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00076148:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00076148:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 0.912391 seconds.
----------------------------------------
timeLevel=00077062:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00077062:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00077062:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 0.220073 seconds.
----------------------------------------
timeLevel=00077283:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00077283:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00077283:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 7.262728 seconds.
----------------------------------------
timeLevel=00083715:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00084554:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00084554:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00084554:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 3.896827 seconds.
----------------------------------------
timeLevel=00088455:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00088455:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00088456:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.323691 seconds.
----------------------------------------
timeLevel=00089781:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00089781:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00089782:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.930985 seconds.
----------------------------------------
timeLevel=00093720:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=False)
----------------------------------------
timeLevel=00096720:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00096720:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00096720:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 2.101519 seconds.
----------------------------------------
timeLevel=00098039:DEBUG
logger=google.cloud.pubsub_v1.subscriber._consumer
threadName=Thread-gRPC-ConsumeRequestIterator
Sending initial request: subscription: "projects/precise-truck-742/subscriptions/s-djh-local-1511933732759"
stream_ack_deadline_seconds: 10

----------------------------------------
timeLevel=00098824:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00098824:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00098825:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 8.454835 seconds.
----------------------------------------
timeLevel=00103730:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00107288:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00107289:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00107289:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 5.841185 seconds.
----------------------------------------
timeLevel=00113136:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00113136:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00113136:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 7.274900 seconds.
----------------------------------------
timeLevel=00113741:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00120419:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00120419:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00120419:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.551626 seconds.
----------------------------------------
timeLevel=00123751:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00126978:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00126978:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00126978:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.373908 seconds.
----------------------------------------
timeLevel=00133359:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00133359:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00133359:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 5.299753 seconds.
----------------------------------------
timeLevel=00133762:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00138665:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00138665:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00138665:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 4.695553 seconds.
----------------------------------------
timeLevel=00143366:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00143366:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00143366:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.495122 seconds.
----------------------------------------
timeLevel=00143772:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00149867:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00149867:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00149867:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 0.614896 seconds.
----------------------------------------
timeLevel=00150483:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00150483:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00150483:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 4.355027 seconds.
----------------------------------------
timeLevel=00153777:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00154843:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00154843:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00154843:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 4.774698 seconds.
----------------------------------------
timeLevel=00159623:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00159623:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00159624:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.244534 seconds.
----------------------------------------
timeLevel=00163788:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00165875:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00165875:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00165875:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 3.659826 seconds.
----------------------------------------
timeLevel=00169539:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00169539:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00169539:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 7.978535 seconds.
----------------------------------------
timeLevel=00173792:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00177526:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00177526:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00177527:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 2.328007 seconds.
----------------------------------------
timeLevel=00179857:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00179858:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00179858:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 2.310174 seconds.
----------------------------------------
timeLevel=00182171:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00182171:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00182171:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 0.164239 seconds.
----------------------------------------
timeLevel=00182336:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00182336:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00182336:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 3.402440 seconds.
----------------------------------------
timeLevel=00183802:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00185742:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00185743:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00185743:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.586543 seconds.
----------------------------------------
timeLevel=00187331:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00187332:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00187332:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 8.427482 seconds.
----------------------------------------
timeLevel=00193813:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00195768:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00195768:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00195768:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.493567 seconds.
----------------------------------------
timeLevel=00197264:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00197264:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00197264:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 7.709286 seconds.
----------------------------------------
timeLevel=00203823:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00204982:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00204982:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00204982:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.848895 seconds.
----------------------------------------
timeLevel=00206833:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00206833:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00206833:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 0.521717 seconds.
----------------------------------------
timeLevel=00207356:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00207356:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00207356:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 1.984807 seconds.
----------------------------------------
timeLevel=00209344:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00209344:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00209344:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 6.301801 seconds.
----------------------------------------
timeLevel=00213825:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future (running=True, done=True)
----------------------------------------
timeLevel=00215653:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
The current p99 value is 10 seconds.
----------------------------------------
timeLevel=00215653:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Renewing lease for 0 ack IDs.
----------------------------------------
timeLevel=00215653:DEBUG
logger=google.cloud.pubsub_v1.subscriber.policy.base
threadName=Thread-LeaseMaintenance
Snoozing lease management for 8.336502 seconds.
----------------------------------------
Exception in thread Consumer helper: consume bidirectional stream:
Traceback (most recent call last):
  File ".../google/cloud/pubsub_v1/subscriber/_consumer.py", line 234, in _blocking_consume
    for response in response_generator:
  File ".../grpc/_channel.py", line 348, in __next__
    return self._next()
  File ".../grpc/_channel.py", line 342, 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])>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "${HOME}/.pyenv/versions/3.6.3/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "${HOME}/.pyenv/versions/3.6.3/lib/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File ".../google/cloud/pubsub_v1/subscriber/_consumer.py", line 248, in _blocking_consume
    self._policy.on_exception(exc)
  File ".../google/cloud/pubsub_v1/subscriber/policy/thread.py", line 163, in on_exception
    self._future.set_exception(exception)
  File ".../google/cloud/pubsub_v1/futures.py", line 159, in set_exception
    raise RuntimeError('set_exception can only be called once.')
RuntimeError: set_exception can only be called once.

timeLevel=00223828:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future exception:
<_Rendezvous of RPC that terminated with (StatusCode.UNAVAILABLE, The service was unable to fulfill your request. Please try again. [code=8a75])>
----------------------------------------
timeLevel=00223829:INFO
logger=REPRO.4234
threadName=MainThread
sub.open() future completed.is_set()? True
----------------------------------------