Resolver TimeoutError

[islue]

I updated to commit 7c7da82 and the backup hung up after a TimeoutError exception. I retried for several times and all ended up with process's hanging.
I am using Percona Server for MongoDB 3.2 and I think it worked in 1.0.1 (with some patches such as bson encode). Any idea?

[2017-05-16 06:58:32,013] [INFO] [MainProcess] [Task:compression:38] Setting Resolver compression method: gzip
[2017-05-16 06:58:32,013] [INFO] [MainProcess] [Resolver:run:91] Resolving oplogs (options: threads=8, compression=gzip)
[2017-05-16 06:58:32,029] [DEBUG] [PoolWorker-8] [Oplog:open:30] Opening oplog file /var/lib/mongodb-consistent-backup/audience/20170516_0542/ps-rs1/dump/oplog.bson
[2017-05-16 06:58:32,030] [DEBUG] [PoolWorker-8] [Oplog:open:30] Opening oplog file /var/lib/mongodb-consistent-backup/audience/20170516_0542/ps-rs1/oplog-tailed.bson
[2017-05-16 06:58:32,030] [INFO] [PoolWorker-8] [ResolverThread:run:30] Resolving oplog for ip-10-1-15-43:27017 to max ts: Timestamp(1494917906, 0)
[2017-05-16 06:58:32,037] [DEBUG] [PoolWorker-9] [Oplog:open:30] Opening oplog file /var/lib/mongodb-consistent-backup/audience/20170516_0542/ps-rs0/dump/oplog.bson
[2017-05-16 06:58:32,038] [DEBUG] [MainProcess] [Resolver:wait:77] Waiting for 3 oplog resolver thread(s) to stop
[2017-05-16 06:58:32,039] [DEBUG] [PoolWorker-9] [Oplog:open:30] Opening oplog file /var/lib/mongodb-consistent-backup/audience/20170516_0542/ps-rs0/oplog-tailed.bson
[2017-05-16 06:58:32,039] [INFO] [PoolWorker-9] [ResolverThread:run:30] Resolving oplog for ip-10-1-15-239:27017 to max ts: Timestamp(1494917906, 0)
[2017-05-16 06:58:32,039] [DEBUG] [PoolWorker-10] [Oplog:open:30] Opening oplog file /var/lib/mongodb-consistent-backup/audience/20170516_0542/ps-rsc/dump/oplog.bson
[2017-05-16 06:58:32,040] [DEBUG] [PoolWorker-10] [Oplog:open:30] Opening oplog file /var/lib/mongodb-consistent-backup/audience/20170516_0542/ps-rsc/oplog-tailed.bson
[2017-05-16 06:58:32,040] [INFO] [PoolWorker-10] [ResolverThread:run:30] Resolving oplog for ip-10-1-12-46:27019 to max ts: Timestamp(1494917906, 0)

Traceback (most recent call last):
  File "/var/lib/mongodb-consistent-backup/.pex/install/mongodb_consistent_backup-1.0.1-py2-none-any.whl.b9b798d133a47c06550dbd36a7afa63e6729fcac/mongodb_consistent_backup-1.0.1-py2-none-any.whl/mongodb_consistent_backup/__init__.py", line 15, in run
    m.run()
  File "/var/lib/mongodb-consistent-backup/.pex/install/mongodb_consistent_backup-1.0.1-py2-none-any.whl.b9b798d133a47c06550dbd36a7afa63e6729fcac/mongodb_consistent_backup-1.0.1-py2-none-any.whl/mongodb_consistent_backup/Main.py", line 420, in run
    resolver_summary = self.resolver.run()
  File "/var/lib/mongodb-consistent-backup/.pex/install/mongodb_consistent_backup-1.0.1-py2-none-any.whl.b9b798d133a47c06550dbd36a7afa63e6729fcac/mongodb_consistent_backup-1.0.1-py2-none-any.whl/mongodb_consistent_backup/Oplog/Resolver/Resolver.py", line 125, in run
    self.wait()
  File "/var/lib/mongodb-consistent-backup/.pex/install/mongodb_consistent_backup-1.0.1-py2-none-any.whl.b9b798d133a47c06550dbd36a7afa63e6729fcac/mongodb_consistent_backup-1.0.1-py2-none-any.whl/mongodb_consistent_backup/Oplog/Resolver/Resolver.py", line 84, in wait
    raise e
TimeoutError
[2017-05-16 06:58:56,127] [DEBUG] [PoolWorker-10] [ResolverThread:close:60] Closing oplog file handles
[2017-05-16 06:58:56,128] [DEBUG] [PoolWorker-10] [ResolverThread:close:66] Removing temporary/tailed oplog file: /var/lib/mongodb-consistent-backup/audience/20170516_0542/ps-rsc/oplog-tailed.bson
[2017-05-16 06:58:56,129] [INFO] [PoolWorker-10] [ResolverThread:run:55] Applied 294329 oplog changes to ip-10-1-12-46:27019 oplog, end ts: Timestamp(1494917906, 1)
[2017-05-16 06:59:00,490] [DEBUG] [PoolWorker-9] [ResolverThread:close:60] Closing oplog file handles
[2017-05-16 06:59:00,490] [DEBUG] [PoolWorker-9] [ResolverThread:close:66] Removing temporary/tailed oplog file: /var/lib/mongodb-consistent-backup/audience/20170516_0542/ps-rs0/oplog-tailed.bson
[2017-05-16 06:59:00,500] [INFO] [PoolWorker-9] [ResolverThread:run:55] Applied 12040 oplog changes to ip-10-1-15-239:27017 oplog, end ts: Timestamp(1494917906, 1)
[2017-05-16 06:59:06,690] [DEBUG] [PoolWorker-8] [ResolverThread:close:60] Closing oplog file handles
[2017-05-16 06:59:06,690] [DEBUG] [PoolWorker-8] [ResolverThread:close:66] Removing temporary/tailed oplog file: /var/lib/mongodb-consistent-backup/audience/20170516_0542/ps-rs1/oplog-tailed.bson
[2017-05-16 06:59:06,700] [INFO] [PoolWorker-8] [ResolverThread:run:55] Applied 122145 oplog changes to ip-10-1-15-43:27017 oplog, end ts: Timestamp(1494917906, 1)

[timvaillancourt]

Thanks for reporting this @islue. This seems due to some fixes in the commit you mentioned.

Could you please try this branch, this should resolve it: https://github.com/timvaillancourt/mongodb_consistent_backup/tree/resolverthread_wait_timeout

Git:

git clone -b resolverthread_wait_timeout https://github.com/Percona-Lab/mongodb_consistent_backup
cd mongodb_consistent_backup
make
...

[timvaillancourt]

This should be resolved by this release: https://github.com/Percona-Lab/mongodb_consistent_backup/releases/tag/1.0.2.

Please confirm

[islue]

It works. Thank you.