ResolverThread not end

[peterhenryfirst]

Hi again,

I have another problem, when I run the tool, with this configuration file:

<test.conf>

production:
  host: 22.6.48.124
  port: 30010
  username: <user>
  password: ******
  log_dir: /home/vagrant/mgbackup/log
  backup:
    method: mongodump
    name: test
    location: /home/vagrant/shared
    mongodump:
      binary: /home/vagrant/mgbin/mongodump
  archive:
    method: tar
  notify:
    method: none
  upload:
    method: none

The process do not finish, and the last log shows that the process is trying to resolve the oplog:

[vagrant@mongobackupboxcentos bin]$ ./mongodb-consistent-backup --config /home/vagrant/mgbackup/conf/test.conf
[2017-04-28 07:53:59,383] [INFO] [MainProcess] [Main:init:127] Starting mongodb-consistent-backup version 1.0.0 (git commit: d780ad545b603d3a2f807e1813f1de407e81f1ba)
[2017-04-28 07:53:59,383] [INFO] [MainProcess] [Main:init:128] Loaded config: {"archive": {"method": "tar", "tar": {"compression": "gzip"}, "zbackup": {"binary": "/usr/bin/zbackup", "cache_mb": 128, "compression": "lzma"}}, "authdb": "admin", "backup": {"location": "/home/vagrant/shared", "method": "mongodump", "mongodump": {"binary": "/home/vagrant/mgbin/mongodump", "compression": "gzip"}, "name": "test"}, "configPath": "/home/vagrant/mgbackup/conf/test.conf", "environment": "production", "host": "22.6.48.124", "lock_file": "/tmp/mongodb-consistent-backup.lock", "log_dir": "/home/vagrant/mgbackup/log", "notify": {"method": "none"}, "oplog": {"compression": "none", "tailer": {"status_interval": 30}}, "password": "******", "port": 30010, "replication": {"max_lag_secs": 5, "max_priority": 1000}, "sharding": {"balancer": {"ping_secs": 3, "wait_secs": 300}}, "upload": {"method": "none", "s3": {"chunk_size_mb": 50, "threads": 4}}, "username": "<user>"}
[2017-04-28 07:53:59,490] [INFO] [MainProcess] [State:init:127] Initializing root state directory /home/vagrant/shared/test
[2017-04-28 07:53:59,558] [INFO] [MainProcess] [State:load_backups:145] Found 0 existing completed backups for set
[2017-04-28 07:53:59,571] [INFO] [MainProcess] [State:init:111] Initializing backup state directory: /home/vagrant/shared/test/20170428_0753
[2017-04-28 07:53:59,582] [INFO] [MainProcess] [Stage:init:32] Notify stage disabled, skipping
[2017-04-28 07:53:59,583] [INFO] [MainProcess] [Stage:init:32] Upload stage disabled, skipping
[2017-04-28 07:53:59,583] [INFO] [MainProcess] [Main:run:305] Running backup in sharding mode using seed node(s): 22.6.48.124:30010
[2017-04-28 07:53:59,620] [INFO] [MainProcess] [Sharding:get_start_state:43] Began with balancer state running: True
[2017-04-28 07:53:59,670] [INFO] [MainProcess] [Sharding:get_config_server:145] Found sharding config server: CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000
[2017-04-28 07:53:59,716] [INFO] [MainProcess] [Sharding:stop_balancer:106] Stopping the balancer and waiting a max of 300 sec
[2017-04-28 07:53:59,759] [INFO] [MainProcess] [Sharding:stop_balancer:117] Balancer stopped after 0.04 seconds
[2017-04-28 07:53:59,942] [INFO] [MainProcess] [Main:run:360] Backup method supports compression, disabling compression in archive step and enabling oplog compression
[2017-04-28 07:53:59,943] [INFO] [MainProcess] [Task:compression:38] Setting Tar compression method: none
[2017-04-28 07:53:59,943] [INFO] [MainProcess] [Task:compression:38] Setting Tailer compression method: gzip
[2017-04-28 07:53:59,943] [INFO] [MainProcess] [Tailer:run:41] Starting oplog tailers on all replica sets (options: compression=gzip, status_secs=30)
[2017-04-28 07:53:59,975] [INFO] [MainProcess] [Replset:find_primary:132] Found PRIMARY: CSRSA_PNUX/22.6.48.124:30000 with optime Timestamp(1493365879, 1)
[2017-04-28 07:53:59,975] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY CSRSA_PNUX/22.6.48.125:30000: {'priority': 1, 'configsvr': True, 'lag': 0.0, 'optime': Timestamp(1493365879, 1), 'score': 100}
[2017-04-28 07:53:59,976] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY CSRSA_PNUX/22.6.48.126:30000: {'priority': 1, 'configsvr': True, 'lag': 0.0, 'optime': Timestamp(1493365879, 1), 'score': 100}
[2017-04-28 07:53:59,976] [INFO] [MainProcess] [Replset:find_secondary:215] Choosing SECONDARY CSRSA_PNUX/22.6.48.125:30000 for replica set CSRSA_PNUX (score: 100)
[2017-04-28 07:53:59,995] [INFO] [TailThread-2] [TailThread:run:64] Tailing oplog on CSRSA_PNUX/22.6.48.125:30000 for changes
[2017-04-28 07:54:00,510] [INFO] [MainProcess] [Replset:find_primary:132] Found PRIMARY: RSA_PNUX/22.6.48.124:30001 with optime Timestamp(1493109944, 111)
[2017-04-28 07:54:00,511] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY RSA_PNUX/22.6.48.125:30001: {'priority': 1, 'lag': 0, 'optime': Timestamp(1493109944, 111), 'score': 100}
[2017-04-28 07:54:00,511] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY RSA_PNUX/22.6.48.126:30001: {'priority': 1, 'lag': 0, 'optime': Timestamp(1493109944, 111), 'score': 100}
[2017-04-28 07:54:00,511] [INFO] [MainProcess] [Replset:find_secondary:215] Choosing SECONDARY RSA_PNUX/22.6.48.125:30001 for replica set RSA_PNUX (score: 100)
[2017-04-28 07:54:00,531] [INFO] [TailThread-3] [TailThread:run:64] Tailing oplog on RSA_PNUX/22.6.48.125:30001 for changes
[2017-04-28 07:54:01,024] [INFO] [MainProcess] [Stage:run:83] Running stage mongodb_consistent_backup.Backup with task: Mongodump
[2017-04-28 07:54:01,030] [INFO] [MainProcess] [Mongodump:run:134] Starting backups using mongodump r3.4.4 (options: compression=gzip, threads_per_dump=1)
[2017-04-28 07:54:01,064] [INFO] [MongodumpThread-4] [MongodumpThread:run:96] Starting mongodump backup of CSRSA_PNUX/22.6.48.125:30000
[2017-04-28 07:54:01,065] [INFO] [MongodumpThread-5] [MongodumpThread:run:96] Starting mongodump backup of RSA_PNUX/22.6.48.125:30001
[2017-04-28 07:54:01,232] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      writing admin.system.users to
[2017-04-28 07:54:01,244] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      done dumping admin.system.users (1 document)
[2017-04-28 07:54:01,244] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      writing admin.system.version to
[2017-04-28 07:54:01,256] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      done dumping admin.system.version (1 document)
[2017-04-28 07:54:01,262] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      writing test.example to
[2017-04-28 07:54:01,348] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing admin.system.users to
[2017-04-28 07:54:01,371] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping admin.system.users (1 document)
[2017-04-28 07:54:01,371] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing admin.system.version to
[2017-04-28 07:54:01,392] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping admin.system.version (1 document)
[2017-04-28 07:54:01,409] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing config.shards to
[2017-04-28 07:54:01,438] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.shards (1 document)
[2017-04-28 07:54:01,439] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing config.chunks to
[2017-04-28 07:54:01,489] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.chunks (0 documents)
[2017-04-28 07:54:01,490] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing config.mongos to
[2017-04-28 07:54:01,520] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.mongos (2 documents)
[2017-04-28 07:54:01,521] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing config.lockpings to
[2017-04-28 07:54:01,559] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.lockpings (5 documents)
[2017-04-28 07:54:01,559] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing config.settings to
[2017-04-28 07:54:01,599] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.settings (1 document)
[2017-04-28 07:54:01,600] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing config.version to
[2017-04-28 07:54:01,644] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.version (1 document)
[2017-04-28 07:54:01,644] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing config.locks to
[2017-04-28 07:54:01,692] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.locks (2 documents)
[2017-04-28 07:54:01,692] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing config.databases to
[2017-04-28 07:54:01,744] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.databases (1 document)
[2017-04-28 07:54:01,744] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing config.tags to
[2017-04-28 07:54:01,797] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.tags (0 documents)
[2017-04-28 07:54:01,798] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing config.changelog to
[2017-04-28 07:54:01,858] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.changelog (1 document)
[2017-04-28 07:54:01,876] [INFO] [MongodumpThread-4] [MongodumpThread:wait:71] CSRSA_PNUX/22.6.48.125:30000:    writing captured oplog to
[2017-04-28 07:54:02,449] [INFO] [MongodumpThread-4] [MongodumpThread:run:132] Backup CSRSA_PNUX/22.6.48.125:30000 completed in 1.38 seconds, 2 oplog changes, end ts: Timestamp(1493365882, 2)
[2017-04-28 07:54:04,111] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      [##......................]  test.example  32/300  (10.7%)
[2017-04-28 07:54:07,111] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      [#####...................]  test.example  67/300  (22.3%)
[2017-04-28 07:54:10,111] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      [########................]  test.example  102/300  (34.0%)
[2017-04-28 07:54:13,112] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      [##########..............]  test.example  137/300  (45.7%)
[2017-04-28 07:54:16,111] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      [#############...........]  test.example  172/300  (57.3%)
[2017-04-28 07:54:18,411] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      [########################]  test.example  300/300  (100.0%)
[2017-04-28 07:54:18,412] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      done dumping test.example (300 documents)
[2017-04-28 07:54:18,415] [INFO] [MongodumpThread-5] [MongodumpThread:wait:71] RSA_PNUX/22.6.48.125:30001:      writing captured oplog to
[2017-04-28 07:54:18,644] [INFO] [MongodumpThread-5] [MongodumpThread:run:132] Backup RSA_PNUX/22.6.48.125:30001 completed in 17.58 seconds, 0 oplog changes
[2017-04-28 07:54:22,558] [INFO] [MainProcess] [Mongodump:wait:88] All mongodump backups completed successfully
[2017-04-28 07:54:22,559] [INFO] [MainProcess] [Stage:run:92] Completed running stage mongodb_consistent_backup.Backup with task Mongodump in 21.53 seconds
[2017-04-28 07:54:22,568] [INFO] [MainProcess] [Tailer:stop:70] Stopping all oplog tailers
[2017-04-28 07:54:22,678] [INFO] [TailThread-3] [TailThread:run:120] Done tailing oplog on RSA_PNUX/22.6.48.125:30001, 0 oplog changes
[2017-04-28 07:54:23,823] [INFO] [TailThread-2] [TailThread:run:120] Done tailing oplog on CSRSA_PNUX/22.6.48.125:30000, 11 oplog changes, end ts: Timestamp(1493365898, 4)
[2017-04-28 07:54:24,581] [INFO] [MainProcess] [Tailer:stop:110] Oplog tailing completed in 24.64 seconds
[2017-04-28 07:54:24,592] [INFO] [MainProcess] [Sharding:restore_balancer_state:98] Restoring balancer state to: True
[2017-04-28 07:54:24,690] [INFO] [MainProcess] [Task:compression:38] Setting Resolver compression method: gzip
[2017-04-28 07:54:24,690] [INFO] [MainProcess] [Resolver:run:84] Resolving oplogs (options: threads=2, compression=gzip)
[2017-04-28 07:54:24,703] [INFO] [MainProcess] [Resolver:run:96] No oplog changes to resolve for 22.6.48.125:30001
[2017-04-28 07:54:24,709] [INFO] [PoolWorker-6] [ResolverThread:run:29] Resolving oplog for 22.6.48.125:30000 to max ts: Timestamp(1493365898, 0)
Killed
[vagrant@mongobackupboxcentos bin]$

Finally I killed the process because it run for more than one hour and maybe the oplog is empty or do not have operations.

Is it possible the configuration or my deployment is not correct?

[timvaillancourt]

Thanks for this report @peterhenryfirst. That's an odd one.

I haven't been able to reproduce this myself yet, could you try running this again with '--verbose' and provide the verbose log output?

[peterhenryfirst]

Hi @timvaillancourt

Sure, this is the log with '--verbose' option active:

[vagrant@mongobackupboxcentos bin]$ ./mongodb-consistent-backup --config /home/vagrant/mgbackup/conf/test.conf --verbose
[2017-05-05 09:49:19,318] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /tmp/mongodb-consistent-backup.lock
[2017-05-05 09:49:19,360] [INFO] [MainProcess] [Main:init:127] Starting mongodb-consistent-backup version 1.0.1 (git commit: GIT_COMMIT_HASH)
[2017-05-05 09:49:19,361] [INFO] [MainProcess] [Main:init:128] Loaded config: {"archive": {"method": "tar", "tar": {"compression": "gzip"}, "zbackup": {"binary": "/usr/bin/zbackup", "cache_mb": 128, "compression": "lzma"}}, "authdb": "admin", "backup": {"location": "/home/vagrant/shared", "method":
"mongodump", "mongodump": {"binary": "/home/vagrant/mgbin/mongodump", "compression": "gzip"}, "name": "tscloud"}, "configPath": "/home/vagrant/mgbackup/conf/test.conf", "environment": "production", "host": "22.6.48.124", "lock_file": "/tmp/mongodb-consistent-backup.lock", "log_dir": "/home/vagrant/m
gbackup/log", "notify": {"method": "none"}, "oplog": {"compression": "none", "tailer": {"status_interval": 30}}, "password": "******", "port": 30010, "replication": {"max_lag_secs": 5, "max_priority": 1000}, "sharding": {"balancer": {"ping_secs": 3, "wait_secs": 300}}, "upload": {"method": "none", "
s3": {"chunk_size_mb": 50, "threads": 4}}, "username": "MongoAdmin", "verbose": true}
[2017-05-05 09:49:19,362] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to 22.6.48.124:30010 (replicaSet=None, readPreference=secondaryPreferred)
[2017-05-05 09:49:19,399] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-05 09:49:19,429] [INFO] [MainProcess] [State:init:127] Initializing root state directory /home/vagrant/shared/tscloud
[2017-05-05 09:49:19,459] [INFO] [MainProcess] [State:load_backups:145] Found 0 existing completed backups for set
[2017-05-05 09:49:19,461] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:19,467] [DEBUG] [MainProcess] [State:write:54] Writing StateRoot state file: /home/vagrant/shared/tscloud/mongodb-consistent-backup_META/meta.bson
[2017-05-05 09:49:19,468] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:19,473] [INFO] [MainProcess] [State:init:111] Initializing backup state directory: /home/vagrant/shared/tscloud/20170505_0949
[2017-05-05 09:49:19,474] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170505_0949/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:19,476] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/shared/tscloud/20170505_0949/mongodb-consistent-backup_META/meta.bson
[2017-05-05 09:49:19,476] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170505_0949/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:19,480] [DEBUG] [MainProcess] [Stage:init:49] Loaded stage mongodb_consistent_backup.Archive with task Tar
[2017-05-05 09:49:19,480] [INFO] [MainProcess] [Stage:init:32] Notify stage disabled, skipping
[2017-05-05 09:49:19,480] [INFO] [MainProcess] [Stage:init:32] Upload stage disabled, skipping
[2017-05-05 09:49:19,480] [INFO] [MainProcess] [Main:run:305] Running backup in sharding mode using seed node(s): 22.6.48.124:30010
[2017-05-05 09:49:19,517] [INFO] [MainProcess] [Sharding:get_start_state:43] Began with balancer state running: True
[2017-05-05 09:49:19,523] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to RSA_PNUX/22.6.48.124:30001,22.6.48.125:30001,22.6.48.126:30001 (replicaSet=RSA_PNUX, readPreference=primaryPreferred)
[2017-05-05 09:49:19,546] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-05 09:49:19,574] [INFO] [MainProcess] [Sharding:get_config_server:145] Found sharding config server: CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000
[2017-05-05 09:49:19,574] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000 (replicaSet=CSRSA_PNUX, readPreference=primaryPreferred)
[2017-05-05 09:49:19,594] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-05 09:49:19,620] [INFO] [MainProcess] [Sharding:stop_balancer:106] Stopping the balancer and waiting a max of 300 sec
[2017-05-05 09:49:19,668] [INFO] [MainProcess] [Sharding:stop_balancer:117] Balancer stopped after 0.05 seconds
[2017-05-05 09:49:21,847] [DEBUG] [MainProcess] [Mongodump:can_gzip:51] Mongodump binary supports gzip
[2017-05-05 09:49:21,848] [DEBUG] [MainProcess] [Stage:init:49] Loaded stage mongodb_consistent_backup.Backup with task Mongodump
[2017-05-05 09:49:21,848] [INFO] [MainProcess] [Main:run:360] Backup method supports compression, disabling compression in archive step and enabling oplog compression
[2017-05-05 09:49:21,848] [INFO] [MainProcess] [Task:compression:38] Setting Tar compression method: none
[2017-05-05 09:49:21,849] [INFO] [MainProcess] [Task:compression:38] Setting Tailer compression method: gzip
[2017-05-05 09:49:21,849] [INFO] [MainProcess] [Tailer:run:41] Starting oplog tailers on all replica sets (options: compression=gzip, status_secs=30)
[2017-05-05 09:49:22,001] [INFO] [MainProcess] [Replset:find_primary:132] Found PRIMARY: CSRSA_PNUX/22.6.48.125:30000 with optime Timestamp(1493977523, 4)
[2017-05-05 09:49:22,001] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY CSRSA_PNUX/22.6.48.124:30000: {'priority': 1, 'configsvr': True, 'lag': 0.0, 'optime': Timestamp(1493977523, 4), 'score': 100}
[2017-05-05 09:49:22,001] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY CSRSA_PNUX/22.6.48.126:30000: {'priority': 1, 'configsvr': True, 'lag': 0.0, 'optime': Timestamp(1493977523, 4), 'score': 100}
[2017-05-05 09:49:22,001] [INFO] [MainProcess] [Replset:find_secondary:215] Choosing SECONDARY CSRSA_PNUX/22.6.48.124:30000 for replica set CSRSA_PNUX (score: 100)
[2017-05-05 09:49:22,015] [INFO] [TailThread-2] [TailThread:run:64] Tailing oplog on CSRSA_PNUX/22.6.48.124:30000 for changes
[2017-05-05 09:49:22,016] [DEBUG] [TailThread-2] [DB:connect:33] Getting MongoDB connection to CSRSA_PNUX/22.6.48.124:30000 (replicaSet=CSRSA_PNUX, readPreference=secondary)
[2017-05-05 09:49:22,109] [DEBUG] [TailThread-2] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-05 09:49:22,164] [DEBUG] [TailThread-2] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170505_0949/CSRSA_PNUX/oplog-tailed.bson
[2017-05-05 09:49:22,531] [INFO] [MainProcess] [Replset:find_primary:132] Found PRIMARY: RSA_PNUX/22.6.48.126:30001 with optime Timestamp(1493819405, 1)
[2017-05-05 09:49:22,532] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY RSA_PNUX/22.6.48.124:30001: {'priority': 1, 'lag': 0, 'optime': Timestamp(1493819405, 1), 'score': 100}
[2017-05-05 09:49:22,532] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY RSA_PNUX/22.6.48.125:30001: {'priority': 1, 'lag': 0.0, 'optime': Timestamp(1493819405, 1), 'score': 100}
[2017-05-05 09:49:22,533] [INFO] [MainProcess] [Replset:find_secondary:215] Choosing SECONDARY RSA_PNUX/22.6.48.124:30001 for replica set RSA_PNUX (score: 100)
[2017-05-05 09:49:22,561] [INFO] [TailThread-3] [TailThread:run:64] Tailing oplog on RSA_PNUX/22.6.48.124:30001 for changes
[2017-05-05 09:49:22,563] [DEBUG] [TailThread-3] [DB:connect:33] Getting MongoDB connection to RSA_PNUX/22.6.48.124:30001 (replicaSet=RSA_PNUX, readPreference=secondary)
[2017-05-05 09:49:22,609] [DEBUG] [TailThread-3] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-05 09:49:22,628] [DEBUG] [TailThread-3] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170505_0949/RSA_PNUX/oplog-tailed.bson
[2017-05-05 09:49:23,046] [INFO] [MainProcess] [Stage:run:83] Running stage mongodb_consistent_backup.Backup with task: Mongodump
[2017-05-05 09:49:23,057] [INFO] [MainProcess] [Mongodump:run:134] Starting backups using mongodump r3.4.4 (options: compression=gzip, threads_per_dump=1)
[2017-05-05 09:49:23,087] [INFO] [MongodumpThread-5] [MongodumpThread:run:97] Starting mongodump backup of RSA_PNUX/22.6.48.124:30001
[2017-05-05 09:49:23,089] [INFO] [MongodumpThread-4] [MongodumpThread:run:97] Starting mongodump backup of CSRSA_PNUX/22.6.48.124:30000
[2017-05-05 09:49:23,096] [DEBUG] [MongodumpThread-5] [MongodumpThread:run:108] Running mongodump cmd: ['/home/vagrant/mgbin/mongodump', '--host', u'22.6.48.124', '--port', '30001', '--oplog', '--out', u'/home/vagrant/shared/tscloud/20170505_0949/RSA_PNUX/dump', '--numParallelCollections=1', '--gzip
', '-u', 'MongoAdmin', '-p', '*****']
[2017-05-05 09:49:23,105] [DEBUG] [MongodumpThread-4] [MongodumpThread:run:108] Running mongodump cmd: ['/home/vagrant/mgbin/mongodump', '--host', u'22.6.48.124', '--port', '30000', '--oplog', '--out', u'/home/vagrant/shared/tscloud/20170505_0949/CSRSA_PNUX/dump', '--numParallelCollections=1', '--gz
ip', '-u', 'MongoAdmin', '-p', '****']
[2017-05-05 09:49:23,420] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      writing admin.system.users to
[2017-05-05 09:49:23,465] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      done dumping admin.system.users (1 document)
[2017-05-05 09:49:23,466] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      writing admin.system.version to
[2017-05-05 09:49:23,530] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      done dumping admin.system.version (1 document)
[2017-05-05 09:49:23,562] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      writing test.example to
[2017-05-05 09:49:23,909] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing admin.system.users to
[2017-05-05 09:49:24,048] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping admin.system.users (1 document)
[2017-05-05 09:49:24,048] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing admin.system.version to
[2017-05-05 09:49:24,118] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping admin.system.version (1 document)
[2017-05-05 09:49:24,170] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing config.shards to
[2017-05-05 09:49:24,278] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping config.shards (1 document)
[2017-05-05 09:49:24,279] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing config.chunks to
[2017-05-05 09:49:24,704] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping config.chunks (0 documents)
[2017-05-05 09:49:24,705] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing config.mongos to
[2017-05-05 09:49:24,781] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping config.mongos (2 documents)
[2017-05-05 09:49:24,781] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing config.lockpings to
[2017-05-05 09:49:24,843] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping config.lockpings (6 documents)
[2017-05-05 09:49:24,844] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing config.settings to
[2017-05-05 09:49:24,908] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping config.settings (1 document)
[2017-05-05 09:49:24,908] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing config.version to
[2017-05-05 09:49:25,008] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping config.version (1 document)
[2017-05-05 09:49:25,008] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing config.locks to
[2017-05-05 09:49:25,081] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping config.locks (2 documents)
[2017-05-05 09:49:25,081] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing config.databases to
[2017-05-05 09:49:25,157] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping config.databases (1 document)
[2017-05-05 09:49:25,158] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing config.tags to
[2017-05-05 09:49:25,241] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping config.tags (0 documents)
[2017-05-05 09:49:25,241] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing config.changelog to
[2017-05-05 09:49:25,324] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    done dumping config.changelog (1 document)
[2017-05-05 09:49:25,355] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.124:30000:    writing captured oplog to
[2017-05-05 09:49:26,112] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      [........................]  test.example  12/300  (4.0%)
[2017-05-05 09:49:26,346] [DEBUG] [MongodumpThread-4] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170505_0949/CSRSA_PNUX/dump/oplog.bson
[2017-05-05 09:49:26,348] [DEBUG] [MongodumpThread-4] [Oplog:load:46] Reading oplog file /home/vagrant/shared/tscloud/20170505_0949/CSRSA_PNUX/dump/oplog.bson
[2017-05-05 09:49:26,351] [INFO] [MongodumpThread-4] [MongodumpThread:run:133] Backup CSRSA_PNUX/22.6.48.124:30000 completed in 3.26 seconds, 0 oplog changes
[2017-05-05 09:49:29,112] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      [##......................]  test.example  32/300  (10.7%)
[2017-05-05 09:49:32,112] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      [####....................]  test.example  52/300  (17.3%)
[2017-05-05 09:49:35,112] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      [######..................]  test.example  77/300  (25.7%)
[2017-05-05 09:49:38,112] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      [########................]  test.example  102/300  (34.0%)
[2017-05-05 09:49:41,112] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      [##########..............]  test.example  127/300  (42.3%)
[2017-05-05 09:49:44,112] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      [###########.............]  test.example  147/300  (49.0%)
[2017-05-05 09:49:47,137] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      [#############...........]  test.example  169/300  (56.3%)
[2017-05-05 09:49:50,112] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      [###############.........]  test.example  192/300  (64.0%)
[2017-05-05 09:49:50,672] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      [########################]  test.example  300/300  (100.0%)
[2017-05-05 09:49:50,673] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      done dumping test.example (300 documents)
[2017-05-05 09:49:50,682] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.124:30001:      writing captured oplog to
[2017-05-05 09:49:50,716] [DEBUG] [MongodumpThread-5] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170505_0949/RSA_PNUX/dump/oplog.bson
[2017-05-05 09:49:50,720] [DEBUG] [MongodumpThread-5] [Oplog:load:46] Reading oplog file /home/vagrant/shared/tscloud/20170505_0949/RSA_PNUX/dump/oplog.bson
[2017-05-05 09:49:50,725] [INFO] [MongodumpThread-5] [MongodumpThread:run:133] Backup RSA_PNUX/22.6.48.124:30001 completed in 27.64 seconds, 0 oplog changes
[2017-05-05 09:49:54,592] [INFO] [MainProcess] [Mongodump:wait:88] All mongodump backups completed successfully
[2017-05-05 09:49:54,594] [INFO] [MainProcess] [Stage:run:92] Completed running stage mongodb_consistent_backup.Backup with task Mongodump in 31.55 seconds
[2017-05-05 09:49:54,595] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170505_0949/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:54,600] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/shared/tscloud/20170505_0949/mongodb-consistent-backup_META/meta.bson
[2017-05-05 09:49:54,601] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170505_0949/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:54,602] [INFO] [MainProcess] [Tailer:stop:72] Stopping all oplog tailers
[2017-05-05 09:49:55,301] [DEBUG] [TailThread-3] [TailThread:run:107] Stopping oplog cursor on RSA_PNUX/22.6.48.124:30001
[2017-05-05 09:49:55,304] [INFO] [TailThread-3] [TailThread:run:120] Done tailing oplog on RSA_PNUX/22.6.48.124:30001, 0 oplog changes
[2017-05-05 09:49:56,460] [DEBUG] [TailThread-2] [TailThread:run:107] Stopping oplog cursor on CSRSA_PNUX/22.6.48.124:30000
[2017-05-05 09:49:56,463] [INFO] [TailThread-2] [TailThread:run:120] Done tailing oplog on CSRSA_PNUX/22.6.48.124:30000, 15 oplog changes, end ts: Timestamp(1493977558, 1)
[2017-05-05 09:49:56,623] [INFO] [MainProcess] [Tailer:stop:112] Oplog tailing completed in 34.77 seconds
[2017-05-05 09:49:56,625] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170505_0949/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:56,678] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/shared/tscloud/20170505_0949/mongodb-consistent-backup_META/meta.bson
[2017-05-05 09:49:56,679] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170505_0949/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:56,681] [INFO] [MainProcess] [Sharding:restore_balancer_state:98] Restoring balancer state to: True
[2017-05-05 09:49:56,695] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000
[2017-05-05 09:49:56,716] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170505_0949/RSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:56,717] [DEBUG] [MainProcess] [State:write:54] Writing StateBackupReplset state file: /home/vagrant/shared/tscloud/20170505_0949/RSA_PNUX/mongodb-consistent-backup_META/replset.bson
[2017-05-05 09:49:56,719] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170505_0949/RSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:56,725] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170505_0949/CSRSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:56,727] [DEBUG] [MainProcess] [State:write:54] Writing StateBackupReplset state file: /home/vagrant/shared/tscloud/20170505_0949/CSRSA_PNUX/mongodb-consistent-backup_META/replset.bson
[2017-05-05 09:49:56,728] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170505_0949/CSRSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-05 09:49:56,730] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: RSA_PNUX/22.6.48.124:30001,22.6.48.125:30001,22.6.48.126:30001
[2017-05-05 09:49:56,731] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: 22.6.48.124:30010
[2017-05-05 09:49:56,895] [INFO] [MainProcess] [Task:compression:38] Setting Resolver compression method: gzip
[2017-05-05 09:49:56,895] [INFO] [MainProcess] [Resolver:run:84] Resolving oplogs (options: threads=2, compression=gzip)
[2017-05-05 09:49:56,905] [DEBUG] [PoolWorker-6] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170505_0949/CSRSA_PNUX/dump/oplog.bson
[2017-05-05 09:49:56,908] [INFO] [MainProcess] [Resolver:run:96] No oplog changes to resolve for 22.6.48.124:30001
[2017-05-05 09:49:56,908] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-05 09:49:56,910] [DEBUG] [PoolWorker-6] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170505_0949/CSRSA_PNUX/oplog-tailed.bson
[2017-05-05 09:49:56,912] [INFO] [PoolWorker-6] [ResolverThread:run:29] Resolving oplog for 22.6.48.124:30000 to max ts: Timestamp(1493977558, 0)
[2017-05-05 09:49:56,916] [DEBUG] [PoolWorker-6] [ResolverThread:close:65] Removing temporary/tailed oplog file: /home/vagrant/shared/tscloud/20170505_0949/CSRSA_PNUX/oplog-tailed.bson
[2017-05-05 09:49:58,911] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
...

The last line of log, is repeated until I killed the process.

I hope that is reproducible or show the information that you need.

Please ask me if you need more data ;-)

[carl-peng]

+1 also suffer this kind of issue, but I stuck in Tailer:

p(1494032092, 2)
[2017-05-06 10:06:07,336] [INFO] [MainProcess] [Tailer:stop:94] Waiting for rs1/shard2xxx:27017 tailer to reach ts: Timestamp(1494035757, 42), currrent: Timestamp(1494032092, 2)
[2017-05-06 10:06:07,837] [INFO] [MainProcess] [Tailer:stop:94] Waiting for rs1/shard2xxx:27017 tailer to reach ts: Timestamp(1494035757, 42), currrent: Timestamp(1494032092, 2)
[2017-05-06 10:06:08,339] [INFO] [MainProcess] [Tailer:stop:94] Waiting for rs1/shard2xxx:27017 tailer to reach ts: Timestamp(1494035757, 42), currrent: Timestamp(1494032092, 2)

.....
it's never end until I killed the process.
version: release 1.0.1

[timvaillancourt]

Thanks for these reports @peterhenryfirst and @carl-peng. I'm unable to reproduce this at the moment but I will continue to investigate the cause.

I should have a testing branch available in the next few days to test a fix or at least gather more data on the problem. It would be great if you can try that on your environment when it is ready.

I can say for sure that this issue is due to added thread safety in 1.0. Perhaps 0.3.6 is a good workaround in the meantime. Thanks

[carl-peng]

Hi, @timvaillancourt ,
Thanks a lot for quick reply.
After I try to review settings in my Mongo cluster, I discover that if I adjust priority of members of replicas, the issue is gone. I'm wondering if @peterhenryfirst can also try this way to see if it can solve problem.
Thanks @timvaillancourt .

Carl

[peterhenryfirst]

Hi @carl-peng,

What do I need to change in my Replica Set priorities?

My shard have the default initialization values on Config Server Replication and Sharded Replica Set.

Thanks.

[carl-peng]

Hi, @peterhenryfirst ,
In my case, I saw records in logs to notice me the backup always waits for one shard to be ready, and it caused the Tailer thread never end. I was wondering why it is, so I went and changed priority of members in the issue replica in the shard, say, by cfg["member"][0].priority=2 and rs.reconfig it.
After done that, my issue is gone.
I do not exactly know how it works, but it really saves my day.

Carl

[peterhenryfirst]

Ah, in my case, the backups is realized and finished:

[2017-04-28 07: 54: 22,558] [MainProcess] [Mongodump: wait: 88] All mongodump backups completed successfully

  After that, one of the threads is running and the parent is waiting for one oplog.

  I will try to change the priority in one member of my Replica Set and see if this change solve my problem.

  Thanks.

[peterhenryfirst]

I changed the priority on the Config Servers Replica Set and the Sharded Cluster Replica Set, but the error is the same, the resolver is waiting:

[vagrant@mongobackupboxcentos bin]$ ./mongodb-consistent-backup --config /home/vagrant/mgbackup/conf/test.conf --verbose
[2017-05-09 11:14:17,578] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /tmp/mongodb-consistent-backup.lock
[2017-05-09 11:14:17,589] [INFO] [MainProcess] [Main:init:127] Starting mongodb-consistent-backup version 1.0.1 (git commit: GIT_COMMIT_HASH)
[2017-05-09 11:14:17,590] [INFO] [MainProcess] [Main:init:128] Loaded config: {"archive": {"method": "tar", "tar": {"compression": "gzip"}, "zbackup": {"binary": "/usr/bin/zbackup", "cache_mb": 128, "compression": "lzma"}}, "authdb": "admin", "backup": {"location": "/home/vagrant/shared", "method":
"mongodump", "mongodump": {"binary": "/home/vagrant/mgbin/mongodump", "compression": "gzip"}, "name": "tscloud"}, "configPath": "/home/vagrant/mgbackup/conf/test.conf", "environment": "production", "host": "22.6.48.124", "lock_file": "/tmp/mongodb-consistent-backup.lock", "log_dir": "/home/vagrant/m
gbackup/log", "notify": {"method": "none"}, "oplog": {"compression": "none", "tailer": {"status_interval": 30}}, "password": "******", "port": 30010, "replication": {"max_lag_secs": 5, "max_priority": 1000}, "sharding": {"balancer": {"ping_secs": 3, "wait_secs": 300}}, "upload": {"method": "none", "
s3": {"chunk_size_mb": 50, "threads": 4}}, "username": "MongoAdmin", "verbose": true}
[2017-05-09 11:14:17,590] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to 22.6.48.124:30010 (replicaSet=None, readPreference=secondaryPreferred)
[2017-05-09 11:14:17,927] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-09 11:14:18,023] [INFO] [MainProcess] [State:init:127] Initializing root state directory /home/vagrant/shared/tscloud
[2017-05-09 11:14:18,252] [INFO] [MainProcess] [State:load_backups:145] Found 0 existing completed backups for set
[2017-05-09 11:14:18,262] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:18,294] [DEBUG] [MainProcess] [State:write:54] Writing StateRoot state file: /home/vagrant/shared/tscloud/mongodb-consistent-backup_META/meta.bson
[2017-05-09 11:14:18,296] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:18,307] [INFO] [MainProcess] [State:init:111] Initializing backup state directory: /home/vagrant/shared/tscloud/20170509_1114
[2017-05-09 11:14:18,309] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170509_1114/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:18,311] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/shared/tscloud/20170509_1114/mongodb-consistent-backup_META/meta.bson
[2017-05-09 11:14:18,312] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170509_1114/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:18,316] [DEBUG] [MainProcess] [Stage:init:49] Loaded stage mongodb_consistent_backup.Archive with task Tar
[2017-05-09 11:14:18,316] [INFO] [MainProcess] [Stage:init:32] Notify stage disabled, skipping
[2017-05-09 11:14:18,316] [INFO] [MainProcess] [Stage:init:32] Upload stage disabled, skipping
[2017-05-09 11:14:18,316] [INFO] [MainProcess] [Main:run:305] Running backup in sharding mode using seed node(s): 22.6.48.124:30010
[2017-05-09 11:14:18,355] [INFO] [MainProcess] [Sharding:get_start_state:43] Began with balancer state running: True
[2017-05-09 11:14:18,375] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to RSA_PNUX/22.6.48.124:30001,22.6.48.125:30001,22.6.48.126:30001 (replicaSet=RSA_PNUX, readPreference=primaryPreferred)
[2017-05-09 11:14:18,422] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-09 11:14:18,450] [INFO] [MainProcess] [Sharding:get_config_server:145] Found sharding config server: CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000
[2017-05-09 11:14:18,450] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000 (replicaSet=CSRSA_PNUX, readPreference=primaryPreferred)
[2017-05-09 11:14:18,471] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-09 11:14:18,518] [INFO] [MainProcess] [Sharding:stop_balancer:106] Stopping the balancer and waiting a max of 300 sec
[2017-05-09 11:14:18,582] [INFO] [MainProcess] [Sharding:stop_balancer:117] Balancer stopped after 0.06 seconds
[2017-05-09 11:14:18,830] [DEBUG] [MainProcess] [Mongodump:can_gzip:51] Mongodump binary supports gzip
[2017-05-09 11:14:18,830] [DEBUG] [MainProcess] [Stage:init:49] Loaded stage mongodb_consistent_backup.Backup with task Mongodump
[2017-05-09 11:14:18,830] [INFO] [MainProcess] [Main:run:360] Backup method supports compression, disabling compression in archive step and enabling oplog compression
[2017-05-09 11:14:18,831] [INFO] [MainProcess] [Task:compression:38] Setting Tar compression method: none
[2017-05-09 11:14:18,831] [INFO] [MainProcess] [Task:compression:38] Setting Tailer compression method: gzip
[2017-05-09 11:14:18,831] [INFO] [MainProcess] [Tailer:run:41] Starting oplog tailers on all replica sets (options: compression=gzip, status_secs=30)
[2017-05-09 11:14:18,884] [INFO] [MainProcess] [Replset:find_primary:132] Found PRIMARY: CSRSA_PNUX/22.6.48.124:30000 with optime Timestamp(1494328391, 5)
[2017-05-09 11:14:18,885] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY CSRSA_PNUX/22.6.48.125:30000: {'priority': 1, 'configsvr': True, 'lag': 0, 'optime': Timestamp(1494328391, 5), 'score': 100}
[2017-05-09 11:14:18,885] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY CSRSA_PNUX/22.6.48.126:30000: {'priority': 1, 'configsvr': True, 'lag': 0, 'optime': Timestamp(1494328391, 5), 'score': 100}
[2017-05-09 11:14:18,885] [INFO] [MainProcess] [Replset:find_secondary:215] Choosing SECONDARY CSRSA_PNUX/22.6.48.125:30000 for replica set CSRSA_PNUX (score: 100)
[2017-05-09 11:14:18,913] [INFO] [TailThread-2] [TailThread:run:64] Tailing oplog on CSRSA_PNUX/22.6.48.125:30000 for changes
[2017-05-09 11:14:18,917] [DEBUG] [TailThread-2] [DB:connect:33] Getting MongoDB connection to CSRSA_PNUX/22.6.48.125:30000 (replicaSet=CSRSA_PNUX, readPreference=secondary)
[2017-05-09 11:14:18,955] [DEBUG] [TailThread-2] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-09 11:14:18,982] [DEBUG] [TailThread-2] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170509_1114/CSRSA_PNUX/oplog-tailed.bson
[2017-05-09 11:14:19,418] [INFO] [MainProcess] [Replset:find_primary:132] Found PRIMARY: RSA_PNUX/22.6.48.124:30001 with optime Timestamp(1494328291, 1)
[2017-05-09 11:14:19,419] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY RSA_PNUX/22.6.48.125:30001: {'priority': 1, 'lag': 0, 'optime': Timestamp(1494328291, 1), 'score': 100}
[2017-05-09 11:14:19,419] [INFO] [MainProcess] [Replset:find_secondary:204] Found SECONDARY RSA_PNUX/22.6.48.126:30001: {'priority': 1, 'lag': 0, 'optime': Timestamp(1494328291, 1), 'score': 100}
[2017-05-09 11:14:19,420] [INFO] [MainProcess] [Replset:find_secondary:215] Choosing SECONDARY RSA_PNUX/22.6.48.125:30001 for replica set RSA_PNUX (score: 100)
[2017-05-09 11:14:19,449] [INFO] [TailThread-3] [TailThread:run:64] Tailing oplog on RSA_PNUX/22.6.48.125:30001 for changes
[2017-05-09 11:14:19,451] [DEBUG] [TailThread-3] [DB:connect:33] Getting MongoDB connection to RSA_PNUX/22.6.48.125:30001 (replicaSet=RSA_PNUX, readPreference=secondary)
[2017-05-09 11:14:19,501] [DEBUG] [TailThread-3] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-09 11:14:19,527] [DEBUG] [TailThread-3] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170509_1114/RSA_PNUX/oplog-tailed.bson
[2017-05-09 11:14:19,933] [INFO] [MainProcess] [Stage:run:83] Running stage mongodb_consistent_backup.Backup with task: Mongodump
[2017-05-09 11:14:19,942] [INFO] [MainProcess] [Mongodump:run:134] Starting backups using mongodump r3.4.4 (options: compression=gzip, threads_per_dump=1)
[2017-05-09 11:14:19,972] [INFO] [MongodumpThread-5] [MongodumpThread:run:97] Starting mongodump backup of RSA_PNUX/22.6.48.125:30001
[2017-05-09 11:14:19,973] [INFO] [MongodumpThread-4] [MongodumpThread:run:97] Starting mongodump backup of CSRSA_PNUX/22.6.48.125:30000
[2017-05-09 11:14:19,978] [DEBUG] [MongodumpThread-5] [MongodumpThread:run:108] Running mongodump cmd: ['/home/vagrant/mgbin/mongodump', '--host', u'22.6.48.125', '--port', '30001', '--oplog', '--out', u'/home/vagrant/shared/tscloud/20170509_1114/RSA_PNUX/dump', '--numParallelCollections=1', '--gzip
', '-u', 'MongoAdmin', '-p', '*****']
[2017-05-09 11:14:19,980] [DEBUG] [MongodumpThread-4] [MongodumpThread:run:108] Running mongodump cmd: ['/home/vagrant/mgbin/mongodump', '--host', u'22.6.48.125', '--port', '30000', '--oplog', '--out', u'/home/vagrant/shared/tscloud/20170509_1114/CSRSA_PNUX/dump', '--numParallelCollections=1', '--gz
ip', '-u', 'MongoAdmin', '-p', '*****']
[2017-05-09 11:14:20,116] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      writing admin.system.users to
[2017-05-09 11:14:20,127] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      done dumping admin.system.users (1 document)
[2017-05-09 11:14:20,127] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      writing admin.system.version to
[2017-05-09 11:14:20,165] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      done dumping admin.system.version (1 document)
[2017-05-09 11:14:20,170] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      writing test.example to
[2017-05-09 11:14:20,477] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing admin.system.users to
[2017-05-09 11:14:20,497] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping admin.system.users (1 document)
[2017-05-09 11:14:20,498] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing admin.system.version to
[2017-05-09 11:14:20,556] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping admin.system.version (1 document)
[2017-05-09 11:14:20,569] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing config.shards to
[2017-05-09 11:14:20,586] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.shards (1 document)
[2017-05-09 11:14:20,587] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing config.chunks to
[2017-05-09 11:14:20,604] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.chunks (0 documents)
[2017-05-09 11:14:20,604] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing config.mongos to
[2017-05-09 11:14:20,621] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.mongos (2 documents)
[2017-05-09 11:14:20,621] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing config.lockpings to
[2017-05-09 11:14:20,641] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.lockpings (17 documents)
[2017-05-09 11:14:20,641] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing config.settings to
[2017-05-09 11:14:20,659] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.settings (1 document)
[2017-05-09 11:14:20,660] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing config.version to
[2017-05-09 11:14:20,677] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.version (1 document)
[2017-05-09 11:14:20,678] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing config.locks to
[2017-05-09 11:14:20,696] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.locks (2 documents)
[2017-05-09 11:14:20,696] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing config.databases to
[2017-05-09 11:14:20,716] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.databases (1 document)
[2017-05-09 11:14:20,716] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing config.tags to
[2017-05-09 11:14:20,733] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.tags (0 documents)
[2017-05-09 11:14:20,734] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing config.changelog to
[2017-05-09 11:14:20,770] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.changelog (1 document)
[2017-05-09 11:14:20,777] [INFO] [MongodumpThread-4] [MongodumpThread:wait:72] CSRSA_PNUX/22.6.48.125:30000:    writing captured oplog to
[2017-05-09 11:14:21,971] [DEBUG] [MongodumpThread-4] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170509_1114/CSRSA_PNUX/dump/oplog.bson
[2017-05-09 11:14:21,973] [DEBUG] [MongodumpThread-4] [Oplog:load:46] Reading oplog file /home/vagrant/shared/tscloud/20170509_1114/CSRSA_PNUX/dump/oplog.bson
[2017-05-09 11:14:21,978] [INFO] [MongodumpThread-4] [MongodumpThread:run:133] Backup CSRSA_PNUX/22.6.48.125:30000 completed in 2.00 seconds, 0 oplog changes
[2017-05-09 11:14:23,004] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      [##......................]  test.example  27/300  (9.0%)
[2017-05-09 11:14:26,004] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      [####....................]  test.example  62/300  (20.7%)
[2017-05-09 11:14:29,004] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      [#######.................]  test.example  97/300  (32.3%)
[2017-05-09 11:14:32,004] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      [##########..............]  test.example  132/300  (44.0%)
[2017-05-09 11:14:35,004] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      [#############...........]  test.example  167/300  (55.7%)
[2017-05-09 11:14:37,524] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      [########################]  test.example  300/300  (100.0%)
[2017-05-09 11:14:37,525] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      done dumping test.example (300 documents)
[2017-05-09 11:14:37,529] [INFO] [MongodumpThread-5] [MongodumpThread:wait:72] RSA_PNUX/22.6.48.125:30001:      writing captured oplog to
[2017-05-09 11:14:37,833] [DEBUG] [MongodumpThread-5] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170509_1114/RSA_PNUX/dump/oplog.bson
[2017-05-09 11:14:37,837] [DEBUG] [MongodumpThread-5] [Oplog:load:46] Reading oplog file /home/vagrant/shared/tscloud/20170509_1114/RSA_PNUX/dump/oplog.bson
[2017-05-09 11:14:37,842] [INFO] [MongodumpThread-5] [MongodumpThread:run:133] Backup RSA_PNUX/22.6.48.125:30001 completed in 17.87 seconds, 0 oplog changes
[2017-05-09 11:14:41,482] [INFO] [MainProcess] [Mongodump:wait:88] All mongodump backups completed successfully
[2017-05-09 11:14:41,484] [INFO] [MainProcess] [Stage:run:92] Completed running stage mongodb_consistent_backup.Backup with task Mongodump in 21.55 seconds
[2017-05-09 11:14:41,488] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170509_1114/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:41,498] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/shared/tscloud/20170509_1114/mongodb-consistent-backup_META/meta.bson
[2017-05-09 11:14:41,500] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170509_1114/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:41,502] [INFO] [MainProcess] [Tailer:stop:72] Stopping all oplog tailers
[2017-05-09 11:14:41,586] [DEBUG] [TailThread-3] [TailThread:run:107] Stopping oplog cursor on RSA_PNUX/22.6.48.125:30001
[2017-05-09 11:14:41,589] [INFO] [TailThread-3] [TailThread:run:120] Done tailing oplog on RSA_PNUX/22.6.48.125:30001, 0 oplog changes
[2017-05-09 11:14:42,972] [DEBUG] [TailThread-2] [TailThread:run:107] Stopping oplog cursor on CSRSA_PNUX/22.6.48.125:30000
[2017-05-09 11:14:42,975] [INFO] [TailThread-2] [TailThread:run:120] Done tailing oplog on CSRSA_PNUX/22.6.48.125:30000, 11 oplog changes, end ts: Timestamp(1494328411, 4)
[2017-05-09 11:14:43,517] [INFO] [MainProcess] [Tailer:stop:112] Oplog tailing completed in 24.69 seconds
[2017-05-09 11:14:43,520] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170509_1114/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:43,534] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/shared/tscloud/20170509_1114/mongodb-consistent-backup_META/meta.bson
[2017-05-09 11:14:43,535] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170509_1114/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:43,538] [INFO] [MainProcess] [Sharding:restore_balancer_state:98] Restoring balancer state to: True
[2017-05-09 11:14:43,544] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000
[2017-05-09 11:14:43,578] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170509_1114/RSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:43,580] [DEBUG] [MainProcess] [State:write:54] Writing StateBackupReplset state file: /home/vagrant/shared/tscloud/20170509_1114/RSA_PNUX/mongodb-consistent-backup_META/replset.bson
[2017-05-09 11:14:43,583] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170509_1114/RSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:43,593] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170509_1114/CSRSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:43,597] [DEBUG] [MainProcess] [State:write:54] Writing StateBackupReplset state file: /home/vagrant/shared/tscloud/20170509_1114/CSRSA_PNUX/mongodb-consistent-backup_META/replset.bson
[2017-05-09 11:14:43,600] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170509_1114/CSRSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-09 11:14:43,604] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: RSA_PNUX/22.6.48.124:30001,22.6.48.125:30001,22.6.48.126:30001
[2017-05-09 11:14:43,606] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: 22.6.48.124:30010
[2017-05-09 11:14:43,678] [INFO] [MainProcess] [Task:compression:38] Setting Resolver compression method: gzip
[2017-05-09 11:14:43,678] [INFO] [MainProcess] [Resolver:run:84] Resolving oplogs (options: threads=2, compression=gzip)
[2017-05-09 11:14:43,693] [DEBUG] [PoolWorker-6] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170509_1114/CSRSA_PNUX/dump/oplog.bson
[2017-05-09 11:14:43,697] [INFO] [MainProcess] [Resolver:run:96] No oplog changes to resolve for 22.6.48.125:30001
[2017-05-09 11:14:43,698] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:14:43,700] [DEBUG] [PoolWorker-6] [Oplog:open:29] Opening oplog file /home/vagrant/shared/tscloud/20170509_1114/CSRSA_PNUX/oplog-tailed.bson
[2017-05-09 11:14:43,704] [INFO] [PoolWorker-6] [ResolverThread:run:29] Resolving oplog for 22.6.48.125:30000 to max ts: Timestamp(1494328411, 0)
[2017-05-09 11:14:43,710] [DEBUG] [PoolWorker-6] [ResolverThread:close:65] Removing temporary/tailed oplog file: /home/vagrant/shared/tscloud/20170509_1114/CSRSA_PNUX/oplog-tailed.bson
[2017-05-09 11:14:45,700] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:16:51,852] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:16:53,854] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:16:55,857] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:16:57,860] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:16:59,862] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:17:01,863] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:17:03,865] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:17:05,868] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:17:07,869] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:17:09,872] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-09 11:17:11,874] [DEBUG] [MainProcess] [Resolver:wait:76] Waiting for 1 oplog resolver thread(s) to stop
Killed
[vagrant@mongobackupboxcentos bin]$

I will use the branch that @timvaillancourt is preparing to test.

[timvaillancourt]

I'm still not 100% sure of the cause of this issue and cannot reproduce it myself, but there are many variables in a mongodb deployment.

I've noticed the code is not passing exceptions from the Resolver threads to the main process. This branch (https://github.com/timvaillancourt/mongodb_consistent_backup/tree/issue_121_test1) will now pass exceptions in ResolverThread.py to the main thread, meaning whatever issue the threads are encountering will now return proper errors and stop the backup. I believe this will capture the problem.

This branch includes other changes for the upcoming 1.0.2 release, including one fix for bson parsing problems with utf8 that may have caused this issue.

Unfortunately that's all I've had time to do for this issue right now. If anyone can run this branch and return any exceptions, that will help bring us one step closer to the solution.

To get this branch:

git clone -b issue_121_test1 https://github.com/timvaillancourt/mongodb_consistent_backup

[peterhenryfirst]

Hi @timvaillancourt,

I run the branch you posted, and this is the result:

[vagrant@mongobackupboxcentos bin]$ ./mongodb-consistent-backup --config /home/vagrant/mgbackup/conf/test.conf --verbose
[2017-05-12 06:24:30,023] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /tmp/mongodb-consistent-backup.lock
[2017-05-12 06:24:30,035] [INFO] [MainProcess] [Main:init:127] Starting mongodb-consistent-backup version 1.0.1 (git commit: ff6c63acda6ce96237a4a7301f4c038456e0c241)
[2017-05-12 06:24:30,035] [INFO] [MainProcess] [Main:init:128] Loaded config: {"archive": {"method": "tar", "tar": {"compression": "gzip"}, "zbackup": {"binary": "/usr/bin/zbackup", "cache_mb": 128, "compression": "lzma"}}, "authdb": "admin", "backup": {"location": "/home/vagrant/shared", "method":
"mongodump", "mongodump": {"binary": "/home/vagrant/mgbin/mongodump", "compression": "auto"}, "name": "tscloud"}, "configPath": "/home/vagrant/mgbackup/conf/test.conf", "environment": "production", "host": "22.6.48.124", "lock_file": "/tmp/mongodb-consistent-backup.lock", "log_dir": "/home/vagrant/m
gbackup/log", "notify": {"method": "none"}, "oplog": {"compression": "none", "tailer": {"status_interval": 30}}, "password": "******", "port": 30010, "replication": {"max_lag_secs": 5, "max_priority": 1000}, "sharding": {"balancer": {"ping_secs": 3, "wait_secs": 300}}, "upload": {"method": "none", "
s3": {"chunk_size_mb": 50, "threads": 4}}, "username": "MongoAdmin", "verbose": true}
[2017-05-12 06:24:30,036] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to 22.6.48.124:30010 (replicaSet=None, readPreference=secondaryPreferred)
[2017-05-12 06:24:30,056] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-12 06:24:30,127] [INFO] [MainProcess] [State:init:127] Initializing root state directory /home/vagrant/shared/tscloud
[2017-05-12 06:24:30,310] [INFO] [MainProcess] [State:load_backups:145] Found 0 existing completed backups for set
[2017-05-12 06:24:30,313] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:30,327] [DEBUG] [MainProcess] [State:write:54] Writing StateRoot state file: /home/vagrant/shared/tscloud/mongodb-consistent-backup_META/meta.bson
[2017-05-12 06:24:30,328] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:30,338] [INFO] [MainProcess] [State:init:111] Initializing backup state directory: /home/vagrant/shared/tscloud/20170512_0624
[2017-05-12 06:24:30,340] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170512_0624/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:30,342] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/shared/tscloud/20170512_0624/mongodb-consistent-backup_META/meta.bson
[2017-05-12 06:24:30,344] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170512_0624/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:30,350] [DEBUG] [MainProcess] [Stage:init:49] Loaded stage mongodb_consistent_backup.Archive with task Tar
[2017-05-12 06:24:30,350] [INFO] [MainProcess] [Stage:init:32] Notify stage disabled, skipping
[2017-05-12 06:24:30,350] [INFO] [MainProcess] [Stage:init:32] Upload stage disabled, skipping
[2017-05-12 06:24:30,351] [INFO] [MainProcess] [Main:run:305] Running backup in sharding mode using seed node(s): 22.6.48.124:30010
[2017-05-12 06:24:30,400] [INFO] [MainProcess] [Sharding:get_start_state:43] Began with balancer state running: True
[2017-05-12 06:24:30,408] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to RSA_PNUX/22.6.48.124:30001,22.6.48.125:30001,22.6.48.126:30001 (replicaSet=RSA_PNUX, readPreference=primaryPreferred)
[2017-05-12 06:24:30,430] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-12 06:24:30,461] [INFO] [MainProcess] [Sharding:get_config_server:145] Found sharding config server: CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000
[2017-05-12 06:24:30,461] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000 (replicaSet=CSRSA_PNUX, readPreference=primaryPreferred)
[2017-05-12 06:24:30,482] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-12 06:24:30,508] [INFO] [MainProcess] [Sharding:stop_balancer:106] Stopping the balancer and waiting a max of 300 sec
[2017-05-12 06:24:30,549] [INFO] [MainProcess] [Sharding:stop_balancer:117] Balancer stopped after 0.04 seconds
[2017-05-12 06:24:30,738] [DEBUG] [MainProcess] [Mongodump:can_gzip:55] Mongodump binary supports gzip
[2017-05-12 06:24:30,739] [INFO] [MainProcess] [Mongodump:choose_compression:48] Mongodump binary supports gzip compression, auto-enabling gzip compression
[2017-05-12 06:24:30,739] [INFO] [MainProcess] [Task:compression:38] Setting Mongodump compression method: gzip
[2017-05-12 06:24:30,739] [DEBUG] [MainProcess] [Stage:init:49] Loaded stage mongodb_consistent_backup.Backup with task Mongodump
[2017-05-12 06:24:30,740] [INFO] [MainProcess] [Main:run:360] Backup method supports compression, disabling compression in archive step and enabling oplog compression
[2017-05-12 06:24:30,740] [INFO] [MainProcess] [Task:compression:38] Setting Tar compression method: none
[2017-05-12 06:24:30,740] [INFO] [MainProcess] [Task:compression:38] Setting Tailer compression method: gzip
[2017-05-12 06:24:30,740] [INFO] [MainProcess] [Tailer:run:41] Starting oplog tailers on all replica sets (options: compression=gzip, status_secs=30)
[2017-05-12 06:24:30,777] [INFO] [MainProcess] [Replset:find_primary:132] Found PRIMARY: CSRSA_PNUX/22.6.48.124:30000 with optime Timestamp(1494570039, 1)
[2017-05-12 06:24:30,777] [INFO] [MainProcess] [Replset:find_secondary:205] Found SECONDARY CSRSA_PNUX/22.6.48.125:30000: {'priority': 1, 'configsvr': True, 'lag': 4.0, 'optime': Timestamp(1494570034, 1), 'score': 92}
[2017-05-12 06:24:30,778] [INFO] [MainProcess] [Replset:find_secondary:205] Found SECONDARY CSRSA_PNUX/22.6.48.126:30000: {'priority': 1, 'configsvr': True, 'lag': 4.0, 'optime': Timestamp(1494570034, 1), 'score': 92}
[2017-05-12 06:24:30,778] [INFO] [MainProcess] [Replset:find_secondary:215] Choosing SECONDARY CSRSA_PNUX/22.6.48.125:30000 for replica set CSRSA_PNUX (score: 92)
[2017-05-12 06:24:30,800] [INFO] [TailThread-2] [TailThread:run:64] Tailing oplog on CSRSA_PNUX/22.6.48.125:30000 for changes
[2017-05-12 06:24:30,803] [DEBUG] [TailThread-2] [DB:connect:33] Getting MongoDB connection to CSRSA_PNUX/22.6.48.125:30000 (replicaSet=CSRSA_PNUX, readPreference=secondary)
[2017-05-12 06:24:30,833] [DEBUG] [TailThread-2] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-12 06:24:30,853] [DEBUG] [TailThread-2] [Oplog:open:30] Opening oplog file /home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/oplog-tailed.bson
[2017-05-12 06:24:31,348] [INFO] [MainProcess] [Replset:find_primary:132] Found PRIMARY: RSA_PNUX/22.6.48.124:30001 with optime Timestamp(1494412104, 1)
[2017-05-12 06:24:31,349] [INFO] [MainProcess] [Replset:find_secondary:205] Found SECONDARY RSA_PNUX/22.6.48.125:30001: {'priority': 1, 'lag': 0.0, 'optime': Timestamp(1494412104, 1), 'score': 100}
[2017-05-12 06:24:31,349] [INFO] [MainProcess] [Replset:find_secondary:205] Found SECONDARY RSA_PNUX/22.6.48.126:30001: {'priority': 1, 'lag': 0.0, 'optime': Timestamp(1494412104, 1), 'score': 100}
[2017-05-12 06:24:31,349] [INFO] [MainProcess] [Replset:find_secondary:215] Choosing SECONDARY RSA_PNUX/22.6.48.125:30001 for replica set RSA_PNUX (score: 100)
[2017-05-12 06:24:31,365] [INFO] [TailThread-3] [TailThread:run:64] Tailing oplog on RSA_PNUX/22.6.48.125:30001 for changes
[2017-05-12 06:24:31,366] [DEBUG] [TailThread-3] [DB:connect:33] Getting MongoDB connection to RSA_PNUX/22.6.48.125:30001 (replicaSet=RSA_PNUX, readPreference=secondary)
[2017-05-12 06:24:31,393] [DEBUG] [TailThread-3] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-12 06:24:31,411] [DEBUG] [TailThread-3] [Oplog:open:30] Opening oplog file /home/vagrant/shared/tscloud/20170512_0624/RSA_PNUX/oplog-tailed.bson
[2017-05-12 06:24:31,860] [INFO] [MainProcess] [Stage:run:83] Running stage mongodb_consistent_backup.Backup with task: Mongodump
[2017-05-12 06:24:31,870] [INFO] [MainProcess] [Mongodump:run:139] Starting backups using mongodump r3.4.4 (options: compression=gzip, threads_per_dump=1)
[2017-05-12 06:24:31,890] [INFO] [MongodumpThread-4] [MongodumpThread:run:100] Starting mongodump backup of CSRSA_PNUX/22.6.48.125:30000
[2017-05-12 06:24:31,892] [INFO] [MongodumpThread-5] [MongodumpThread:run:100] Starting mongodump backup of RSA_PNUX/22.6.48.125:30001
[2017-05-12 06:24:31,900] [DEBUG] [MongodumpThread-4] [MongodumpThread:run:111] Running mongodump cmd: ['/home/vagrant/mgbin/mongodump', '--host', u'22.6.48.125', '--port', '30000', '--oplog', '--out', u'/home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/dump', '--numParallelCollections=1', '--gz
ip', '--readPreference=secondary', '-u', 'MongoAdmin', '-p', '****']
[2017-05-12 06:24:31,935] [DEBUG] [MongodumpThread-5] [MongodumpThread:run:111] Running mongodump cmd: ['/home/vagrant/mgbin/mongodump', '--host', u'22.6.48.125', '--port', '30001', '--oplog', '--out', u'/home/vagrant/shared/tscloud/20170512_0624/RSA_PNUX/dump', '--numParallelCollections=1', '--gzip
', '--readPreference=secondary', '-u', 'MongoAdmin', '-p', '****']
[2017-05-12 06:24:32,062] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      writing admin.system.users to
[2017-05-12 06:24:32,072] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      done dumping admin.system.users (1 document)
[2017-05-12 06:24:32,072] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      writing admin.system.version to
[2017-05-12 06:24:32,081] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      done dumping admin.system.version (1 document)
[2017-05-12 06:24:32,089] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      writing BPNUX001.CPNUX001 to
[2017-05-12 06:24:32,099] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      done dumping BPNUX001.CPNUX001 (1 document)
[2017-05-12 06:24:32,100] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      writing test.example to
[2017-05-12 06:24:32,130] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing admin.system.users to
[2017-05-12 06:24:32,146] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping admin.system.users (3 documents)
[2017-05-12 06:24:32,146] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing admin.system.version to
[2017-05-12 06:24:32,162] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping admin.system.version (1 document)
[2017-05-12 06:24:32,172] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.shards to
[2017-05-12 06:24:32,191] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.shards (1 document)
[2017-05-12 06:24:32,192] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.chunks to
[2017-05-12 06:24:32,212] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.chunks (0 documents)
[2017-05-12 06:24:32,212] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.mongos to
[2017-05-12 06:24:32,230] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.mongos (2 documents)
[2017-05-12 06:24:32,231] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.lockpings to
[2017-05-12 06:24:32,249] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.lockpings (17 documents)
[2017-05-12 06:24:32,249] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.settings to
[2017-05-12 06:24:32,266] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.settings (1 document)
[2017-05-12 06:24:32,267] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.version to
[2017-05-12 06:24:32,300] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.version (1 document)
[2017-05-12 06:24:32,301] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.locks to
[2017-05-12 06:24:32,319] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.locks (3 documents)
[2017-05-12 06:24:32,320] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.databases to
[2017-05-12 06:24:32,338] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.databases (2 documents)
[2017-05-12 06:24:32,338] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.tags to
[2017-05-12 06:24:32,355] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.tags (0 documents)
[2017-05-12 06:24:32,356] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.changelog to
[2017-05-12 06:24:32,374] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.changelog (1 document)
[2017-05-12 06:24:32,380] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing captured oplog to
[2017-05-12 06:24:33,321] [DEBUG] [MongodumpThread-4] [Oplog:open:30] Opening oplog file /home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/dump/oplog.bson
[2017-05-12 06:24:33,324] [DEBUG] [MongodumpThread-4] [Oplog:load:47] Reading oplog file /home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/dump/oplog.bson
[2017-05-12 06:24:33,332] [INFO] [MongodumpThread-4] [MongodumpThread:run:136] Backup CSRSA_PNUX/22.6.48.125:30000 completed in 1.44 seconds, 4 oplog changes, end ts: Timestamp(1494570041, 4)
[2017-05-12 06:24:34,947] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [##......................]  test.example  32/300  (10.7%)
[2017-05-12 06:24:37,949] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [#####...................]  test.example  67/300  (22.3%)
[2017-05-12 06:24:40,947] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [########................]  test.example  102/300  (34.0%)
[2017-05-12 06:24:43,947] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [##########..............]  test.example  137/300  (45.7%)
[2017-05-12 06:24:46,947] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [#############...........]  test.example  172/300  (57.3%)
[2017-05-12 06:24:49,271] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [########################]  test.example  300/300  (100.0%)
[2017-05-12 06:24:49,272] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      done dumping test.example (300 documents)
[2017-05-12 06:24:49,275] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      writing captured oplog to
[2017-05-12 06:24:49,607] [DEBUG] [MongodumpThread-5] [Oplog:open:30] Opening oplog file /home/vagrant/shared/tscloud/20170512_0624/RSA_PNUX/dump/oplog.bson
[2017-05-12 06:24:49,612] [DEBUG] [MongodumpThread-5] [Oplog:load:47] Reading oplog file /home/vagrant/shared/tscloud/20170512_0624/RSA_PNUX/dump/oplog.bson
[2017-05-12 06:24:49,616] [INFO] [MongodumpThread-5] [MongodumpThread:run:136] Backup RSA_PNUX/22.6.48.125:30001 completed in 17.72 seconds, 0 oplog changes
[2017-05-12 06:24:53,406] [INFO] [MainProcess] [Mongodump:wait:92] All mongodump backups completed successfully
[2017-05-12 06:24:53,409] [INFO] [MainProcess] [Stage:run:92] Completed running stage mongodb_consistent_backup.Backup with task Mongodump in 21.55 seconds
[2017-05-12 06:24:53,431] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170512_0624/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:53,441] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/shared/tscloud/20170512_0624/mongodb-consistent-backup_META/meta.bson
[2017-05-12 06:24:53,444] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170512_0624/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:53,447] [INFO] [MainProcess] [Tailer:stop:72] Stopping all oplog tailers
[2017-05-12 06:24:54,358] [DEBUG] [TailThread-3] [TailThread:run:107] Stopping oplog cursor on RSA_PNUX/22.6.48.125:30001
[2017-05-12 06:24:54,360] [INFO] [TailThread-3] [TailThread:run:120] Done tailing oplog on RSA_PNUX/22.6.48.125:30001, 0 oplog changes
[2017-05-12 06:24:54,598] [DEBUG] [TailThread-2] [TailThread:run:107] Stopping oplog cursor on CSRSA_PNUX/22.6.48.125:30000
[2017-05-12 06:24:54,601] [INFO] [TailThread-2] [TailThread:run:120] Done tailing oplog on CSRSA_PNUX/22.6.48.125:30000, 14 oplog changes, end ts: Timestamp(1494570063, 1)
[2017-05-12 06:24:55,462] [INFO] [MainProcess] [Tailer:stop:112] Oplog tailing completed in 24.72 seconds
[2017-05-12 06:24:55,465] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170512_0624/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:55,478] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/shared/tscloud/20170512_0624/mongodb-consistent-backup_META/meta.bson
[2017-05-12 06:24:55,480] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170512_0624/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:55,482] [INFO] [MainProcess] [Sharding:restore_balancer_state:98] Restoring balancer state to: True
[2017-05-12 06:24:55,488] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000
[2017-05-12 06:24:55,499] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170512_0624/RSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:55,500] [DEBUG] [MainProcess] [State:write:54] Writing StateBackupReplset state file: /home/vagrant/shared/tscloud/20170512_0624/RSA_PNUX/mongodb-consistent-backup_META/replset.bson
[2017-05-12 06:24:55,503] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170512_0624/RSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:55,511] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:55,512] [DEBUG] [MainProcess] [State:write:54] Writing StateBackupReplset state file: /home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/mongodb-consistent-backup_META/replset.bson
[2017-05-12 06:24:55,515] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 06:24:55,517] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: RSA_PNUX/22.6.48.124:30001,22.6.48.125:30001,22.6.48.126:30001
[2017-05-12 06:24:55,519] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: 22.6.48.124:30010
[2017-05-12 06:24:55,582] [INFO] [MainProcess] [Task:compression:38] Setting Resolver compression method: gzip
[2017-05-12 06:24:55,583] [INFO] [MainProcess] [Resolver:run:91] Resolving oplogs (options: threads=2, compression=gzip)
[2017-05-12 06:24:55,596] [DEBUG] [PoolWorker-6] [Oplog:open:30] Opening oplog file /home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/dump/oplog.bson
[2017-05-12 06:24:55,599] [INFO] [MainProcess] [Resolver:run:103] No oplog changes to resolve for 22.6.48.125:30001
[2017-05-12 06:24:55,600] [DEBUG] [MainProcess] [Resolver:wait:77] Waiting for 1 oplog resolver thread(s) to stop
[2017-05-12 06:24:55,602] [DEBUG] [PoolWorker-6] [Oplog:open:30] Opening oplog file /home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/oplog-tailed.bson
[2017-05-12 06:24:55,605] [INFO] [PoolWorker-6] [ResolverThread:run:30] Resolving oplog for 22.6.48.125:30000 to max ts: Timestamp(1494570063, 0)
[2017-05-12 06:24:55,613] [DEBUG] [PoolWorker-6] [ResolverThread:close:66] Removing temporary/tailed oplog file: /home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/oplog-tailed.bson
[Errno 26] Text file busy: '/home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/oplog-tailed.bson'
Traceback (most recent call last):
  File "/home/vagrant/.pex/install/mongodb_consistent_backup-1.0.1-py2-none-any.whl.01fba777fd409c75686747f3f6131c6110893acd/mongodb_consistent_backup-1.0.1-py2-none-any.whl/mongodb_consistent_backup/__init__.py", line 15, in run
    m.run()
  File "/home/vagrant/.pex/install/mongodb_consistent_backup-1.0.1-py2-none-any.whl.01fba777fd409c75686747f3f6131c6110893acd/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 "/home/vagrant/.pex/install/mongodb_consistent_backup-1.0.1-py2-none-any.whl.01fba777fd409c75686747f3f6131c6110893acd/mongodb_consistent_backup-1.0.1-py2-none-any.whl/mongodb_consistent_backup/Oplog/Resolver/Resolver.py", line 125, in run
    self.wait()
  File "/home/vagrant/.pex/install/mongodb_consistent_backup-1.0.1-py2-none-any.whl.01fba777fd409c75686747f3f6131c6110893acd/mongodb_consistent_backup-1.0.1-py2-none-any.whl/mongodb_consistent_backup/Oplog/Resolver/Resolver.py", line 84, in wait
    raise e
OSError: [Errno 26] Text file busy: '/home/vagrant/shared/tscloud/20170512_0624/CSRSA_PNUX/oplog-tailed.bson'
[vagrant@mongobackupboxcentos bin]$

The problem was the oplog file, wasn't it?

[timvaillancourt]

Excellent, we get the exception now. This appears to be due to oplog-tailed.bson not being closed cleanly in the code, and this commit should resolve this:

https://github.com/timvaillancourt/mongodb_consistent_backup/commit/0f6aa82085a0a41bebc6a35086dafa60d5c69ddc#diff-cbe34f98d603bd5dc0ec55753f20fc6a

Please try a 'git pull' on the issue_121_test1 branch now. Thanks!

[peterhenryfirst]

Hi @timvaillancourt,

I think the backup is going well! I needed to change the path because the backup path is shared and the symlink is not going very well.

This is the log:

[vagrant@mongobackupboxcentos bin]$ ./mongodb-consistent-backup --config /home/vagrant/mgbackup/conf/test.conf --verbose
[2017-05-12 12:02:59,256] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /tmp/mongodb-consistent-backup.lock
[2017-05-12 12:02:59,257] [INFO] [MainProcess] [Main:init:127] Starting mongodb-consistent-backup version 1.0.1 (git commit: 0f6aa82085a0a41bebc6a35086dafa60d5c69ddc)
[2017-05-12 12:02:59,257] [INFO] [MainProcess] [Main:init:128] Loaded config: {"archive": {"method": "tar", "tar": {"compression": "gzip"}, "zbackup": {"binary": "/usr/bin/zbackup", "cache_mb": 128, "compression": "lzma"}}, "authdb": "admin", "backup": {"location": "/home/vagrant/backup", "method":
"mongodump", "mongodump": {"binary": "/home/vagrant/mgbin/mongodump", "compression": "auto"}, "name": "tscloud"}, "configPath": "/home/vagrant/mgbackup/conf/test.conf", "environment": "production", "host": "22.6.48.124", "lock_file": "/tmp/mongodb-consistent-backup.lock", "log_dir": "/home/vagrant/m
gbackup/log", "notify": {"method": "none"}, "oplog": {"compression": "none", "tailer": {"status_interval": 30}}, "password": "******", "port": 30010, "replication": {"max_lag_secs": 5, "max_priority": 1000}, "sharding": {"balancer": {"ping_secs": 3, "wait_secs": 300}}, "upload": {"method": "none", "
s3": {"chunk_size_mb": 50, "threads": 4}}, "username": "MongoAdmin", "verbose": true}
[2017-05-12 12:02:59,258] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to 22.6.48.124:30010 (replicaSet=None, readPreference=secondaryPreferred)
[2017-05-12 12:02:59,278] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-12 12:02:59,297] [INFO] [MainProcess] [State:init:127] Initializing root state directory /home/vagrant/backup/tscloud
[2017-05-12 12:02:59,297] [INFO] [MainProcess] [State:load_backups:145] Found 0 existing completed backups for set
[2017-05-12 12:02:59,298] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/backup/tscloud/mongodb-consistent-backup_META.lock
[2017-05-12 12:02:59,298] [DEBUG] [MainProcess] [State:write:54] Writing StateRoot state file: /home/vagrant/backup/tscloud/mongodb-consistent-backup_META/meta.bson
[2017-05-12 12:02:59,298] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/backup/tscloud/mongodb-consistent-backup_META.lock
[2017-05-12 12:02:59,298] [INFO] [MainProcess] [State:init:111] Initializing backup state directory: /home/vagrant/backup/tscloud/20170512_1202
[2017-05-12 12:02:59,299] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META.lock
[2017-05-12 12:02:59,299] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META/meta.bson
[2017-05-12 12:02:59,299] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META.lock
[2017-05-12 12:02:59,300] [DEBUG] [MainProcess] [Stage:init:49] Loaded stage mongodb_consistent_backup.Archive with task Tar
[2017-05-12 12:02:59,301] [INFO] [MainProcess] [Stage:init:32] Notify stage disabled, skipping
[2017-05-12 12:02:59,301] [INFO] [MainProcess] [Stage:init:32] Upload stage disabled, skipping
[2017-05-12 12:02:59,301] [INFO] [MainProcess] [Main:run:305] Running backup in sharding mode using seed node(s): 22.6.48.124:30010
[2017-05-12 12:02:59,305] [INFO] [MainProcess] [Sharding:get_start_state:43] Began with balancer state running: True
[2017-05-12 12:02:59,314] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to RSA_PNUX/22.6.48.124:30001,22.6.48.125:30001,22.6.48.126:30001 (replicaSet=RSA_PNUX, readPreference=primaryPreferred)
[2017-05-12 12:02:59,337] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-12 12:02:59,359] [INFO] [MainProcess] [Sharding:get_config_server:145] Found sharding config server: CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000
[2017-05-12 12:02:59,360] [DEBUG] [MainProcess] [DB:connect:33] Getting MongoDB connection to CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000 (replicaSet=CSRSA_PNUX, readPreference=primaryPreferred)
[2017-05-12 12:02:59,379] [DEBUG] [MainProcess] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-12 12:02:59,402] [INFO] [MainProcess] [Sharding:stop_balancer:106] Stopping the balancer and waiting a max of 300 sec
[2017-05-12 12:02:59,432] [INFO] [MainProcess] [Sharding:stop_balancer:117] Balancer stopped after 0.03 seconds
[2017-05-12 12:02:59,446] [DEBUG] [MainProcess] [Mongodump:can_gzip:55] Mongodump binary supports gzip
[2017-05-12 12:02:59,447] [INFO] [MainProcess] [Mongodump:choose_compression:48] Mongodump binary supports gzip compression, auto-enabling gzip compression
[2017-05-12 12:02:59,447] [INFO] [MainProcess] [Task:compression:38] Setting Mongodump compression method: gzip
[2017-05-12 12:02:59,447] [DEBUG] [MainProcess] [Stage:init:49] Loaded stage mongodb_consistent_backup.Backup with task Mongodump
[2017-05-12 12:02:59,447] [INFO] [MainProcess] [Main:run:360] Backup method supports compression, disabling compression in archive step and enabling oplog compression
[2017-05-12 12:02:59,447] [INFO] [MainProcess] [Task:compression:38] Setting Tar compression method: none
[2017-05-12 12:02:59,447] [INFO] [MainProcess] [Task:compression:38] Setting Tailer compression method: gzip
[2017-05-12 12:02:59,447] [INFO] [MainProcess] [Tailer:run:41] Starting oplog tailers on all replica sets (options: compression=gzip, status_secs=30)
[2017-05-12 12:02:59,465] [INFO] [MainProcess] [Replset:find_primary:132] Found PRIMARY: CSRSA_PNUX/22.6.48.124:30000 with optime Timestamp(1494590647, 2)
[2017-05-12 12:02:59,466] [INFO] [MainProcess] [Replset:find_secondary:205] Found SECONDARY CSRSA_PNUX/22.6.48.125:30000: {'priority': 1, 'configsvr': True, 'lag': 0.0, 'optime': Timestamp(1494590647, 2), 'score': 100}
[2017-05-12 12:02:59,466] [INFO] [MainProcess] [Replset:find_secondary:205] Found SECONDARY CSRSA_PNUX/22.6.48.126:30000: {'priority': 1, 'configsvr': True, 'lag': 0.0, 'optime': Timestamp(1494590647, 2), 'score': 100}
[2017-05-12 12:02:59,467] [INFO] [MainProcess] [Replset:find_secondary:215] Choosing SECONDARY CSRSA_PNUX/22.6.48.125:30000 for replica set CSRSA_PNUX (score: 100)
[2017-05-12 12:02:59,480] [INFO] [TailThread-2] [TailThread:run:64] Tailing oplog on CSRSA_PNUX/22.6.48.125:30000 for changes
[2017-05-12 12:02:59,482] [DEBUG] [TailThread-2] [DB:connect:33] Getting MongoDB connection to CSRSA_PNUX/22.6.48.125:30000 (replicaSet=CSRSA_PNUX, readPreference=secondary)
[2017-05-12 12:02:59,512] [DEBUG] [TailThread-2] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-12 12:02:59,529] [DEBUG] [TailThread-2] [Oplog:open:30] Opening oplog file /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/oplog-tailed.bson
[2017-05-12 12:02:59,994] [INFO] [MainProcess] [Replset:find_primary:132] Found PRIMARY: RSA_PNUX/22.6.48.124:30001 with optime Timestamp(1494412104, 1)
[2017-05-12 12:02:59,994] [INFO] [MainProcess] [Replset:find_secondary:205] Found SECONDARY RSA_PNUX/22.6.48.125:30001: {'priority': 1, 'lag': 0, 'optime': Timestamp(1494412104, 1), 'score': 100}
[2017-05-12 12:02:59,995] [INFO] [MainProcess] [Replset:find_secondary:205] Found SECONDARY RSA_PNUX/22.6.48.126:30001: {'priority': 1, 'lag': 0, 'optime': Timestamp(1494412104, 1), 'score': 100}
[2017-05-12 12:02:59,995] [INFO] [MainProcess] [Replset:find_secondary:215] Choosing SECONDARY RSA_PNUX/22.6.48.125:30001 for replica set RSA_PNUX (score: 100)
[2017-05-12 12:03:00,016] [INFO] [TailThread-3] [TailThread:run:64] Tailing oplog on RSA_PNUX/22.6.48.125:30001 for changes
[2017-05-12 12:03:00,018] [DEBUG] [TailThread-3] [DB:connect:33] Getting MongoDB connection to RSA_PNUX/22.6.48.125:30001 (replicaSet=RSA_PNUX, readPreference=secondary)
[2017-05-12 12:03:00,047] [DEBUG] [TailThread-3] [DB:auth_if_required:56] Authenticating connection with username: MongoAdmin
[2017-05-12 12:03:00,065] [DEBUG] [TailThread-3] [Oplog:open:30] Opening oplog file /home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX/oplog-tailed.bson
[2017-05-12 12:03:00,507] [INFO] [MainProcess] [Stage:run:83] Running stage mongodb_consistent_backup.Backup with task: Mongodump
[2017-05-12 12:03:00,518] [INFO] [MainProcess] [Mongodump:run:139] Starting backups using mongodump r3.4.4 (options: compression=gzip, threads_per_dump=1)
[2017-05-12 12:03:00,539] [INFO] [MongodumpThread-4] [MongodumpThread:run:100] Starting mongodump backup of CSRSA_PNUX/22.6.48.125:30000
[2017-05-12 12:03:00,540] [INFO] [MongodumpThread-5] [MongodumpThread:run:100] Starting mongodump backup of RSA_PNUX/22.6.48.125:30001
[2017-05-12 12:03:00,542] [DEBUG] [MongodumpThread-4] [MongodumpThread:run:111] Running mongodump cmd: ['/home/vagrant/mgbin/mongodump', '--host', u'22.6.48.125', '--port', '30000', '--oplog', '--out', u'/home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/dump', '--numParallelCollections=1', '--gz
ip', '--readPreference=secondary', '-u', 'MongoAdmin', '-p', '****']
[2017-05-12 12:03:00,551] [DEBUG] [MongodumpThread-5] [MongodumpThread:run:111] Running mongodump cmd: ['/home/vagrant/mgbin/mongodump', '--host', u'22.6.48.125', '--port', '30001', '--oplog', '--out', u'/home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX/dump', '--numParallelCollections=1', '--gzip
', '--readPreference=secondary', '-u', 'MongoAdmin', '-p', '****']
[2017-05-12 12:03:00,675] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      writing admin.system.users to
[2017-05-12 12:03:00,681] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      done dumping admin.system.users (1 document)
[2017-05-12 12:03:00,681] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      writing admin.system.version to
[2017-05-12 12:03:00,689] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      done dumping admin.system.version (1 document)
[2017-05-12 12:03:00,695] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      writing BPNUX001.CPNUX001 to
[2017-05-12 12:03:00,702] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      done dumping BPNUX001.CPNUX001 (1 document)
[2017-05-12 12:03:00,702] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      writing test.example to
[2017-05-12 12:03:00,724] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing admin.system.users to
[2017-05-12 12:03:00,733] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping admin.system.users (3 documents)
[2017-05-12 12:03:00,733] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing admin.system.version to
[2017-05-12 12:03:00,742] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping admin.system.version (1 document)
[2017-05-12 12:03:00,750] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.shards to
[2017-05-12 12:03:00,760] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.shards (1 document)
[2017-05-12 12:03:00,761] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.chunks to
[2017-05-12 12:03:00,771] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.chunks (0 documents)
[2017-05-12 12:03:00,772] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.mongos to
[2017-05-12 12:03:00,782] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.mongos (2 documents)
[2017-05-12 12:03:00,782] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.lockpings to
[2017-05-12 12:03:00,795] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.lockpings (17 documents)
[2017-05-12 12:03:00,796] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.settings to
[2017-05-12 12:03:00,809] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.settings (1 document)
[2017-05-12 12:03:00,810] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.version to
[2017-05-12 12:03:00,825] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.version (1 document)
[2017-05-12 12:03:00,826] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.locks to
[2017-05-12 12:03:00,844] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.locks (3 documents)
[2017-05-12 12:03:00,844] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.databases to
[2017-05-12 12:03:00,864] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.databases (2 documents)
[2017-05-12 12:03:00,864] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.tags to
[2017-05-12 12:03:00,884] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.tags (0 documents)
[2017-05-12 12:03:00,884] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing config.changelog to
[2017-05-12 12:03:00,907] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    done dumping config.changelog (1 document)
[2017-05-12 12:03:00,916] [INFO] [MongodumpThread-4] [MongodumpThread:wait:73] CSRSA_PNUX/22.6.48.125:30000:    writing captured oplog to
[2017-05-12 12:03:01,605] [DEBUG] [MongodumpThread-4] [Oplog:open:30] Opening oplog file /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/dump/oplog.bson
[2017-05-12 12:03:01,605] [DEBUG] [MongodumpThread-4] [Oplog:load:47] Reading oplog file /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/dump/oplog.bson
[2017-05-12 12:03:01,607] [INFO] [MongodumpThread-4] [MongodumpThread:run:136] Backup CSRSA_PNUX/22.6.48.125:30000 completed in 1.07 seconds, 0 oplog changes
[2017-05-12 12:03:03,568] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [##......................]  test.example  32/300  (10.7%)
[2017-05-12 12:03:06,568] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [#####...................]  test.example  67/300  (22.3%)
[2017-05-12 12:03:09,568] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [########................]  test.example  102/300  (34.0%)
[2017-05-12 12:03:12,568] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [##########..............]  test.example  137/300  (45.7%)
[2017-05-12 12:03:15,568] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [#############...........]  test.example  172/300  (57.3%)
[2017-05-12 12:03:17,829] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      [########################]  test.example  300/300  (100.0%)
[2017-05-12 12:03:17,829] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      done dumping test.example (300 documents)
[2017-05-12 12:03:17,833] [INFO] [MongodumpThread-5] [MongodumpThread:wait:73] RSA_PNUX/22.6.48.125:30001:      writing captured oplog to
[2017-05-12 12:03:18,045] [DEBUG] [MongodumpThread-5] [Oplog:open:30] Opening oplog file /home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX/dump/oplog.bson
[2017-05-12 12:03:18,046] [DEBUG] [MongodumpThread-5] [Oplog:load:47] Reading oplog file /home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX/dump/oplog.bson
[2017-05-12 12:03:18,049] [INFO] [MongodumpThread-5] [MongodumpThread:run:136] Backup RSA_PNUX/22.6.48.125:30001 completed in 17.51 seconds, 0 oplog changes
[2017-05-12 12:03:22,041] [INFO] [MainProcess] [Mongodump:wait:92] All mongodump backups completed successfully
[2017-05-12 12:03:22,043] [INFO] [MainProcess] [Stage:run:92] Completed running stage mongodb_consistent_backup.Backup with task Mongodump in 21.54 seconds
[2017-05-12 12:03:22,043] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:22,044] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META/meta.bson
[2017-05-12 12:03:22,045] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:22,045] [INFO] [MainProcess] [Tailer:stop:72] Stopping all oplog tailers
[2017-05-12 12:03:22,124] [DEBUG] [TailThread-3] [TailThread:run:107] Stopping oplog cursor on RSA_PNUX/22.6.48.125:30001
[2017-05-12 12:03:22,126] [INFO] [TailThread-3] [TailThread:run:120] Done tailing oplog on RSA_PNUX/22.6.48.125:30001, 0 oplog changes
[2017-05-12 12:03:23,080] [DEBUG] [TailThread-2] [TailThread:run:107] Stopping oplog cursor on CSRSA_PNUX/22.6.48.125:30000
[2017-05-12 12:03:23,082] [INFO] [TailThread-2] [TailThread:run:120] Done tailing oplog on CSRSA_PNUX/22.6.48.125:30000, 10 oplog changes, end ts: Timestamp(1494590664, 4)
[2017-05-12 12:03:24,059] [INFO] [MainProcess] [Tailer:stop:112] Oplog tailing completed in 24.61 seconds
[2017-05-12 12:03:24,059] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:24,060] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META/meta.bson
[2017-05-12 12:03:24,060] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:24,061] [INFO] [MainProcess] [Sharding:restore_balancer_state:98] Restoring balancer state to: True
[2017-05-12 12:03:24,066] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: CSRSA_PNUX/22.6.48.124:30000,22.6.48.125:30000,22.6.48.126:30000
[2017-05-12 12:03:24,074] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:24,075] [DEBUG] [MainProcess] [State:write:54] Writing StateBackupReplset state file: /home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX/mongodb-consistent-backup_META/replset.bson
[2017-05-12 12:03:24,076] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:24,078] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:24,078] [DEBUG] [MainProcess] [State:write:54] Writing StateBackupReplset state file: /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/mongodb-consistent-backup_META/replset.bson
[2017-05-12 12:03:24,079] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:24,080] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: RSA_PNUX/22.6.48.124:30001,22.6.48.125:30001,22.6.48.126:30001
[2017-05-12 12:03:24,082] [DEBUG] [MainProcess] [DB:close:122] Closing connection to: 22.6.48.124:30010
[2017-05-12 12:03:24,108] [INFO] [MainProcess] [Task:compression:38] Setting Resolver compression method: gzip
[2017-05-12 12:03:24,109] [INFO] [MainProcess] [Resolver:run:91] Resolving oplogs (options: threads=2, compression=gzip)
[2017-05-12 12:03:24,121] [DEBUG] [PoolWorker-6] [Oplog:open:30] Opening oplog file /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/dump/oplog.bson
[2017-05-12 12:03:24,122] [DEBUG] [PoolWorker-6] [Oplog:open:30] Opening oplog file /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/oplog-tailed.bson
[2017-05-12 12:03:24,122] [INFO] [PoolWorker-6] [ResolverThread:run:30] Resolving oplog for 22.6.48.125:30000 to max ts: Timestamp(1494590664, 0)
[2017-05-12 12:03:24,125] [DEBUG] [PoolWorker-6] [ResolverThread:close:60] Closing oplog file handles
[2017-05-12 12:03:24,126] [DEBUG] [PoolWorker-6] [ResolverThread:close:66] Removing temporary/tailed oplog file: /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/oplog-tailed.bson
[2017-05-12 12:03:24,126] [INFO] [PoolWorker-6] [ResolverThread:run:55] Applied 6 oplog changes to 22.6.48.125:30000 oplog, end ts: Timestamp(1494590664, 1)
[2017-05-12 12:03:24,127] [DEBUG] [MainProcess] [Resolver:done:68] Resolving completed for: 22.6.48.125:30000
[2017-05-12 12:03:24,129] [INFO] [MainProcess] [Resolver:run:103] No oplog changes to resolve for 22.6.48.125:30001
[2017-05-12 12:03:24,130] [INFO] [MainProcess] [Resolver:run:131] Oplog resolving completed in 0.02 seconds
[2017-05-12 12:03:24,131] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:24,132] [DEBUG] [MainProcess] [State:write:54] Writing StateOplog state file: /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/mongodb-consistent-backup_META/oplog.bson
[2017-05-12 12:03:24,132] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:24,133] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:24,134] [DEBUG] [MainProcess] [State:write:54] Writing StateOplog state file: /home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX/mongodb-consistent-backup_META/oplog.bson
[2017-05-12 12:03:24,134] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:24,135] [INFO] [MainProcess] [Stage:run:83] Running stage mongodb_consistent_backup.Archive with task: Tar
[2017-05-12 12:03:24,147] [INFO] [MainProcess] [Tar:run:56] Archiving backup directories with pool of 1 thread(s)
[2017-05-12 12:03:24,148] [DEBUG] [MainProcess] [Tar:wait:45] Waiting for 2 tar thread(s) to stop
[2017-05-12 12:03:24,156] [INFO] [PoolWorker-8] [TarThread:run:41] Archiving directory: /home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX
[2017-05-12 12:03:24,164] [DEBUG] [PoolWorker-8] [LocalCommand:run:56] tar command completed
[2017-05-12 12:03:24,166] [INFO] [PoolWorker-8] [TarThread:run:41] Archiving directory: /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX
[2017-05-12 12:03:24,167] [DEBUG] [MainProcess] [Tar:done:36] Archiving completed for: /home/vagrant/backup/tscloud/20170512_1202/RSA_PNUX
[2017-05-12 12:03:24,173] [DEBUG] [PoolWorker-8] [LocalCommand:run:56] tar command completed
[2017-05-12 12:03:24,174] [DEBUG] [MainProcess] [Tar:done:36] Archiving completed for: /home/vagrant/backup/tscloud/20170512_1202/CSRSA_PNUX
[2017-05-12 12:03:26,150] [DEBUG] [MainProcess] [Tar:wait:48] Stopped all tar threads
[2017-05-12 12:03:26,152] [INFO] [MainProcess] [Stage:run:92] Completed running stage mongodb_consistent_backup.Archive with task Tar in 2.02 seconds
[2017-05-12 12:03:26,153] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:26,154] [DEBUG] [MainProcess] [State:write:54] Writing StateBackup state file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META/meta.bson
[2017-05-12 12:03:26,155] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:26,158] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:26,158] [DEBUG] [MainProcess] [State:write:54] Writing StateDoneStamp state file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META/done.bson
[2017-05-12 12:03:26,159] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /home/vagrant/backup/tscloud/20170512_1202/mongodb-consistent-backup_META.lock
[2017-05-12 12:03:26,159] [INFO] [MainProcess] [Main:update_symlinks:150] Updating tscloud latest symlink to: /home/vagrant/backup/tscloud/20170512_1202
[2017-05-12 12:03:26,162] [INFO] [MainProcess] [Main:run:463] Completed mongodb-consistent-backup in 26.85 sec
[2017-05-12 12:03:26,162] [INFO] [MainProcess] [Logger:rotate:79] Running rotation of log files
[2017-05-12 12:03:26,162] [INFO] [MainProcess] [Logger:compress:58] Compressing previous log file
[2017-05-12 12:03:26,168] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /tmp/mongodb-consistent-backup.lock

This is the result of the backup:

[vagrant@mongobackupboxcentos bin]$ ls -larth /home/vagrant/backup/tscloud/
total 16K
drwxrwxr-x. 3 vagrant vagrant 4.0K May 12 12:02 ..
drwxrwxr-x. 2 vagrant vagrant 4.0K May 12 12:02 mongodb-consistent-backup_META
lrwxrwxrwx. 1 vagrant vagrant   42 May 12 12:03 latest -> /home/vagrant/backup/tscloud/20170512_1202
drwxrwxr-x. 3 vagrant vagrant 4.0K May 12 12:03 20170512_1202
drwxrwxr-x. 4 vagrant vagrant 4.0K May 12 12:03 .
[vagrant@mongobackupboxcentos bin]$

I think this is the correct structure, isn't it?

We need to check if the backup is good with mongorestore. But I will test the next week ;-)

Thanks!