vcsreplicator: logging improvements in bootstrap (Bug 1428466)
authorConnor Sheehan <sheehan@mozilla.com>
Fri, 23 Nov 2018 11:05:41 -0500
changeset 6799 f260c773c13f
parent 6798 550944957db0
child 6800 54de0d1af317
push id3382
push usercosheehan@mozilla.com
push dateWed, 09 Jan 2019 03:35:56 +0000
treeherderversion-control-tools@f260c773c13f [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
bugs1428466
vcsreplicator: logging improvements in bootstrap (Bug 1428466) This commit contains a few of the logging changes I have manually patched onto my test deployments in EC2, and I feel they are useful enough to land in vct. This commit will create a directory at `/var/log/vcsrbootstrap` which will contain 3 separate log files for Kafka consumer logs, Mercurial consumer logs and the logs created by the vcsreplicator bootstrap scripts themselves. Having the three logs in one location makes debugging issues easier.
ansible/roles/hg-ssh/tasks/main.yml
ansible/roles/hg-web/tasks/main.yml
pylib/vcsreplicator/tests/test-bootstrap.t
pylib/vcsreplicator/vcsreplicator/bootstrap.py
--- a/ansible/roles/hg-ssh/tasks/main.yml
+++ b/ansible/roles/hg-ssh/tasks/main.yml
@@ -214,16 +214,23 @@
 
 - name: ensure bundles directory exists
   file: path=/repo/hg/bundles
         state=directory
         owner=hg
         group=hg
         mode=0775
 
+- name: create directory for bootstrap logs
+  file: path=/var/log/vcsrbootstrap
+        state=directory
+        owner=hg
+        group=hg
+        mode=0775
+
 - name: write list of repositories to generate bundles for
   copy: src=bundle-repos
         dest=/repo/hg/bundles/repos
         owner=hg
         group=hg
         mode=0644
 
 - name: install repo unify config files
--- a/ansible/roles/hg-web/tasks/main.yml
+++ b/ansible/roles/hg-web/tasks/main.yml
@@ -609,16 +609,23 @@
 
 - name: directory for vcsreplicator logs
   file: path=/var/log/vcsreplicator
         state=directory
         owner=root
         group=root
         mode=0755
 
+- name: create directory for bootstrap logs
+  file: path=/var/log/vcsrbootstrap
+        state=directory
+        owner=hg
+        group=hg
+        mode=0775
+
 - name: directory for repos deleted through vcsreplicator
   file: path=/repo/hg/todelete
         owner=hg
         group=hg
         mode=0750
         state=directory
 
 - name: systemd service file for vcsreplicator
--- a/pylib/vcsreplicator/tests/test-bootstrap.t
+++ b/pylib/vcsreplicator/tests/test-bootstrap.t
@@ -80,17 +80,30 @@ Explicit exclude "filterrepo" for testin
 
   $ hgmo exec hgweb0 /set-config-option /etc/mercurial/vcsreplicator.ini replicationrules exclude.testrule path:{moz}/filterrepo
   $ hgmo exec hgweb0 /set-config-option /etc/mercurial/vcsreplicator.ini replicationrules include.rest re:\{moz\}/.\*
 
 
 Run hgssh bootstrap procedure and confirm the format of the returned data
 We send the output to a file for use in the hgweb bootstrap procedure
 
-  $ hgmo exec hgssh sudo -u hg -g hg /var/hg/venv_tools/bin/vcsreplicator-bootstrap-hgssh /etc/mercurial/hgrc /var/hg/venv_pash/bin/hg --workers 1 --output /home/hg/hgssh.json > $TESTTMP/hgssh.json
+  $ hgmo exec hgssh sudo -u hg -g hg /var/hg/venv_tools/bin/vcsreplicator-bootstrap-hgssh /etc/mercurial/hgrc /var/hg/venv_pash/bin/hg --workers 1 --output /home/hg/hgssh.json
+  * * vcsreplicator.bootstrap gathered initial Kafka offsets (glob)
+  * * vcsreplicator.bootstrap calling `replicatesync --bootstrap` on /repo/hg/mozilla/deleterepo (glob)
+  * * vcsreplicator.bootstrap calling `replicatesync --bootstrap` on /repo/hg/mozilla/filterrepo (glob)
+  * * vcsreplicator.bootstrap calling `replicatesync --bootstrap` on /repo/hg/mozilla/mozilla-central (glob)
+  * * vcsreplicator.bootstrap calling `replicatesync --bootstrap` on /repo/hg/mozilla/testrepo (glob)
+  * * vcsreplicator.bootstrap called `replicatesync --bootstrap` on /repo/hg/mozilla/deleterepo successfully (glob)
+  * * vcsreplicator.bootstrap called `replicatesync --bootstrap` on /repo/hg/mozilla/filterrepo successfully (glob)
+  * * vcsreplicator.bootstrap called `replicatesync --bootstrap` on /repo/hg/mozilla/mozilla-central successfully (glob)
+  * * vcsreplicator.bootstrap called `replicatesync --bootstrap` on /repo/hg/mozilla/testrepo successfully (glob)
+  * * vcsreplicator.bootstrap gathered final Kafka offsets (glob)
+  {"repositories": ["{moz}/deleterepo", "{moz}/filterrepo", "{moz}/mozilla-central", "{moz}/testrepo"], "offsets": {"0": [6, 8], "1": [0, 0], "2": [10, 12], "3": [0, 0], "4": [0, 0], "5": [0, 0], "6": [0, 0], "7": [0, 0]}}
+  * * vcsreplicator.bootstrap hgssh bootstrap process complete! (glob)
+  * * vcsreplicator.bootstrap writing output to /home/hg/hgssh.json (glob)
   $ hgmo exec hgssh sudo -u hg -g hg cat /home/hg/hgssh.json | python -m json.tool
   {
       "offsets": {
           "0": [
               6,
               8
           ],
           "1": [
@@ -124,59 +137,33 @@ We send the output to a file for use in 
       },
       "repositories": [
           "{moz}/deleterepo",
           "{moz}/filterrepo",
           "{moz}/mozilla-central",
           "{moz}/testrepo"
       ]
   }
-  $ cat $TESTTMP/hgssh.json | python -m json.tool
-  {
-      "offsets": {
-          "0": [
-              6,
-              8
-          ],
-          "1": [
-              0,
-              0
-          ],
-          "2": [
-              10,
-              12
-          ],
-          "3": [
-              0,
-              0
-          ],
-          "4": [
-              0,
-              0
-          ],
-          "5": [
-              0,
-              0
-          ],
-          "6": [
-              0,
-              0
-          ],
-          "7": [
-              0,
-              0
-          ]
-      },
-      "repositories": [
-          "{moz}/deleterepo",
-          "{moz}/filterrepo",
-          "{moz}/mozilla-central",
-          "{moz}/testrepo"
-      ]
-  }
+  $ docker cp $SSH_CID:/home/hg/hgssh.json $TESTTMP/hgssh.json
+
+Check the logs on hgssh
+
+  $ hgmo exec hgssh cat /var/log/vcsrbootstrap/bootstrap.log
+  * * vcsreplicator.bootstrap gathered initial Kafka offsets (glob)
+  * * vcsreplicator.bootstrap calling `replicatesync --bootstrap` on /repo/hg/mozilla/deleterepo (glob)
+  * * vcsreplicator.bootstrap calling `replicatesync --bootstrap` on /repo/hg/mozilla/filterrepo (glob)
+  * * vcsreplicator.bootstrap calling `replicatesync --bootstrap` on /repo/hg/mozilla/mozilla-central (glob)
+  * * vcsreplicator.bootstrap calling `replicatesync --bootstrap` on /repo/hg/mozilla/testrepo (glob)
+  * * vcsreplicator.bootstrap called `replicatesync --bootstrap` on /repo/hg/mozilla/deleterepo successfully (glob)
+  * * vcsreplicator.bootstrap called `replicatesync --bootstrap` on /repo/hg/mozilla/filterrepo successfully (glob)
+  * * vcsreplicator.bootstrap called `replicatesync --bootstrap` on /repo/hg/mozilla/mozilla-central successfully (glob)
+  * * vcsreplicator.bootstrap called `replicatesync --bootstrap` on /repo/hg/mozilla/testrepo successfully (glob)
+  * * vcsreplicator.bootstrap gathered final Kafka offsets (glob)
+  * * vcsreplicator.bootstrap hgssh bootstrap process complete! (glob)
+  * * vcsreplicator.bootstrap writing output to /home/hg/hgssh.json (glob)
 
 Confirm offsets returned by the bootstrap procedure match offsets from a dump
 
   $ hgmo exec hgweb1 /var/hg/venv_replication/bin/vcsreplicator-consumer /etc/mercurial/vcsreplicator.ini --wait-for-no-lag
   $ hgmo exec hgweb1 /var/hg/venv_replication/bin/vcsreplicator-print-offsets /etc/mercurial/vcsreplicator.ini
   topic     group           partition    offset    available    lag (s)
   --------  ------------  -----------  --------  -----------  ---------
   pushdata  *            0         8            8          0 (glob)
@@ -269,60 +256,57 @@ Delete the "deleterepo" to generate an e
 
   $ hgmo exec hgssh sudo rm -rf /repo/hg/mozilla/deleterepo
 
 Perform bootstrap procedure on hgweb. vcsreplicator is still off on this host so any replication
 will be an indication of a successful bootstrap
 
   $ docker cp $TESTTMP/hgssh_edited.json $HGWEB_0_CID:/etc/mercurial/hgssh.json
   $ hgmo exec hgweb0 sudo -u hg -g hg /var/hg/venv_replication/bin/vcsreplicator-bootstrap-hgweb /etc/mercurial/vcsreplicator.ini /etc/mercurial/hgssh.json --workers 1
-  vcsreplicator.bootstrap reading hgssh JSON document
-  vcsreplicator.bootstrap JSON document read
-  vcsreplicator.bootstrap assigning the consumer to partition 0
-  vcsreplicator.bootstrap seeking the consumer to offset 6
-  vcsreplicator.bootstrap partition 0 of topic pushdata moved to offset 6
-  vcsreplicator.bootstrap message on partition 0, offset 6 has been collected
-  vcsreplicator.bootstrap message on partition 0, offset 7 has been collected
-  vcsreplicator.bootstrap finished retrieving messages on partition 0
-  vcsreplicator.bootstrap assigning the consumer to partition 2
-  vcsreplicator.bootstrap seeking the consumer to offset 10
-  vcsreplicator.bootstrap partition 2 of topic pushdata moved to offset 10
-  vcsreplicator.bootstrap message on partition 2, offset 10 has been collected
-  vcsreplicator.bootstrap message on partition 2, offset 11 has been collected
-  vcsreplicator.bootstrap message on partition 2, offset 12 has been collected
-  vcsreplicator.bootstrap message on partition 2, offset 13 has been collected
-  vcsreplicator.bootstrap message on partition 2, offset 14 has been collected
-  vcsreplicator.bootstrap message on partition 2, offset 15 has been collected
-  vcsreplicator.bootstrap finished retrieving messages on partition 2
-  vcsreplicator.bootstrap finished retrieving messages from Kafka
-  vcsreplicator.bootstrap processing messages for partition 0
-  vcsreplicator.bootstrap scheduled clone for {moz}/deleterepo
-  vcsreplicator.bootstrap processing messages for partition 2 (?)
-  vcsreplicator.bootstrap syncing repo: {moz}/deleterepo
-  vcsreplicator.bootstrap processing messages for partition 2 (?)
-  vcsreplicator.bootstrap scheduled clone for {moz}/mozilla-central
-  vcsreplicator.bootstrap syncing repo: {moz}/mozilla-central (?)
-  vcsreplicator.bootstrap scheduled clone for {moz}/testrepo
-  vcsreplicator.bootstrap extra messages found for {moz}/mozilla-central: 1 total
-  vcsreplicator.bootstrap extra messages found for {moz}/mozilla-central: 2 total
-  vcsreplicator.bootstrap exiting sync for: {moz}/deleterepo
-  vcsreplicator.bootstrap syncing repo: {moz}/mozilla-central (?)
-  vcsreplicator.bootstrap error triggering replication of Mercurial repo {moz}/deleterepo: (255, "pulling from ssh://hgssh/deleterepo\nremote: Warning: Permanently added the RSA host key for IP address * to the list of known hosts.\nremote: requested repo deleterepo does not exist", 'abort: no suitable response from remote hg!') (glob)
-  vcsreplicator.bootstrap 2 repositories remaining
-  vcsreplicator.bootstrap exiting sync for: {moz}/mozilla-central
-  vcsreplicator.bootstrap {moz}/mozilla-central successfully cloned (?)
-  vcsreplicator.bootstrap syncing repo: {moz}/testrepo
-  vcsreplicator.bootstrap {moz}/mozilla-central successfully cloned (?)
-  vcsreplicator.bootstrap 1 repositories remaining
-  vcsreplicator.bootstrap scheduling extra processing for {moz}/mozilla-central
-  vcsreplicator.bootstrap exiting sync for: {moz}/testrepo
-  vcsreplicator.bootstrap {moz}/testrepo successfully cloned
-  vcsreplicator.bootstrap 0 repositories remaining
-  vcsreplicator.bootstrap extra processing for {moz}/mozilla-central completed successfully
-  vcsreplicator.bootstrap 0 batches remaining
+  * * vcsreplicator.bootstrap reading hgssh JSON document (glob)
+  * * vcsreplicator.bootstrap JSON document read (glob)
+  * * vcsreplicator.bootstrap assigning the consumer to partition 0 (glob)
+  * * vcsreplicator.bootstrap seeking the consumer to offset 6 (glob)
+  * * vcsreplicator.bootstrap partition 0 of topic pushdata moved to offset 6 (glob)
+  * * vcsreplicator.bootstrap message on partition 0, offset 6 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 0, offset 7 has been collected (glob)
+  * * vcsreplicator.bootstrap finished retrieving messages on partition 0 (glob)
+  * * vcsreplicator.bootstrap assigning the consumer to partition 2 (glob)
+  * * vcsreplicator.bootstrap seeking the consumer to offset 10 (glob)
+  * * vcsreplicator.bootstrap partition 2 of topic pushdata moved to offset 10 (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 10 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 11 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 12 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 13 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 14 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 15 has been collected (glob)
+  * * vcsreplicator.bootstrap finished retrieving messages on partition 2 (glob)
+  * * vcsreplicator.bootstrap finished retrieving messages from Kafka (glob)
+  * * vcsreplicator.bootstrap processing messages for partition 0 (glob)
+  * * vcsreplicator.bootstrap scheduled clone for {moz}/deleterepo (glob)
+  * * vcsreplicator.bootstrap syncing repo: {moz}/deleterepo (glob)
+  * * vcsreplicator.bootstrap processing messages for partition 2 (glob)
+  * * vcsreplicator.bootstrap scheduled clone for {moz}/mozilla-central (glob)
+  * * vcsreplicator.bootstrap scheduled clone for {moz}/testrepo (glob)
+  * * vcsreplicator.bootstrap extra messages found for {moz}/mozilla-central: 1 total (glob)
+  * * vcsreplicator.bootstrap extra messages found for {moz}/mozilla-central: 2 total (glob)
+  * * vcsreplicator.bootstrap exiting sync for: {moz}/deleterepo (glob)
+  * * vcsreplicator.bootstrap syncing repo: {moz}/mozilla-central (glob)
+  * * vcsreplicator.bootstrap error triggering replication of Mercurial repo {moz}/deleterepo: (255, "pulling from ssh://hgssh/deleterepo\nremote: Warning: Permanently added the RSA host key for IP address * to the list of known hosts.\nremote: requested repo deleterepo does not exist", 'abort: no suitable response from remote hg!') (glob)
+  * * vcsreplicator.bootstrap 2 repositories remaining (glob)
+  * * vcsreplicator.bootstrap exiting sync for: {moz}/mozilla-central (glob)
+  * * vcsreplicator.bootstrap syncing repo: {moz}/testrepo (glob)
+  * * vcsreplicator.bootstrap {moz}/mozilla-central successfully cloned (glob)
+  * * vcsreplicator.bootstrap 1 repositories remaining (glob)
+  * * vcsreplicator.bootstrap scheduling extra processing for {moz}/mozilla-central (glob)
+  * * vcsreplicator.bootstrap exiting sync for: {moz}/testrepo (glob)
+  * * vcsreplicator.bootstrap {moz}/testrepo successfully cloned (glob)
+  * * vcsreplicator.bootstrap 0 repositories remaining (glob)
+  * * vcsreplicator.bootstrap extra processing for {moz}/mozilla-central completed successfully (glob)
+  * * vcsreplicator.bootstrap 0 batches remaining (glob)
   * bootstrap process complete (glob)
   [1]
 
 
 Confirm commits replicated to hgweb host
 
   $ hgmo exec hgweb0 /var/hg/venv_replication/bin/hg -R /repo/hg/mozilla/mozilla-central log
   changeset:   1:89e594ce6b79
@@ -397,35 +381,119 @@ bottom of the log file.
   changeset:   2:ba17b5c8e955
   tag:         tip
   user:        Test User <someone@example.com>
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     Another commit
   
 Verify consumer log output. The indicated initial offsets should start at 13, not 0.
 
-  $ hgmo exec hgweb0 tail -n 18 /var/log/vcsreplicator/consumer.log
-  vcsreplicator.consumer starting consumer for topic=pushdata group=* partitions=[2] (glob)
-  vcsreplicator.consumer processing heartbeat-1 from partition 2 offset 16
-  vcsreplicator.consumer processing heartbeat-1 from partition 2 offset 17
-  vcsreplicator.consumer processing hg-changegroup-2 from partition 2 offset 18
-  vcsreplicator.consumer pulling 1 heads (ba17b5c8e955a5e7f57c478cdd75bc999c5460a1) and 1 nodes from ssh://hgssh/mozilla-central into /repo/hg/mozilla/mozilla-central
-  vcsreplicator.consumer   $ /var/hg/venv_replication/bin/hg pull -rba17b5c8e955a5e7f57c478cdd75bc999c5460a1 -- ssh://hgssh/mozilla-central
-  vcsreplicator.consumer   > pulling from ssh://hgssh/mozilla-central
-  vcsreplicator.consumer   > searching for changes
-  vcsreplicator.consumer   > adding changesets
-  vcsreplicator.consumer   > adding manifests
-  vcsreplicator.consumer   > adding file changes
-  vcsreplicator.consumer   > added 1 changesets with 1 changes to 1 files
-  vcsreplicator.consumer   > added 1 pushes
-  vcsreplicator.consumer   > new changesets ba17b5c8e955
-  vcsreplicator.consumer   > (run 'hg update' to get a working copy)
-  vcsreplicator.consumer   [0]
-  vcsreplicator.consumer pulled 1 changesets into /repo/hg/mozilla/mozilla-central
-  vcsreplicator.consumer processing hg-heads-1 from partition 2 offset 19
+  $ hgmo exec hgweb0 cat /var/log/vcsrbootstrap/consumer.log
+  repository does not exist: /repo/hg/mozilla/deleterepo
+  created Mercurial repository: /repo/hg/mozilla/deleterepo
+  pulling 1 heads into /repo/hg/mozilla/deleterepo
+    $ /var/hg/venv_replication/bin/hg pull -r0000000000000000000000000000000000000000 -- ssh://hgssh/deleterepo
+    > pulling from ssh://hgssh/deleterepo
+    > remote: Warning: Permanently added the RSA host key for IP address '*' to the list of known hosts. (glob)
+    > remote: requested repo deleterepo does not exist
+    > abort: no suitable response from remote hg!
+    [255]
+  repository does not exist: /repo/hg/mozilla/mozilla-central
+  created Mercurial repository: /repo/hg/mozilla/mozilla-central
+  writing hgrc: /repo/hg/mozilla/mozilla-central/.hg/hgrc
+  pulling 1 heads into /repo/hg/mozilla/mozilla-central
+    $ /var/hg/venv_replication/bin/hg pull -r7a58fdf00b0fe1fa87fa052d9f78a8f28e1239e0 -- ssh://hgssh/mozilla-central
+    > pulling from ssh://hgssh/mozilla-central
+    > adding changesets
+    > adding manifests
+    > adding file changes
+    > added 1 changesets with 1 changes to 1 files
+    > received pushlog entry for unknown changeset 89e594ce6b790e64021edfe272c70db75e7304ab; ignoring
+    > added 1 pushes
+    > updating moz-owner file
+    > new changesets 7a58fdf00b0f
+    > (run 'hg update' to get a working copy)
+    [0]
+  pulled 1 changesets into /repo/hg/mozilla/mozilla-central
+  repository does not exist: /repo/hg/mozilla/testrepo
+  created Mercurial repository: /repo/hg/mozilla/testrepo
+  writing hgrc: /repo/hg/mozilla/testrepo/.hg/hgrc
+  pulling 1 heads into /repo/hg/mozilla/testrepo
+    $ /var/hg/venv_replication/bin/hg pull -r77538e1ce4bec5f7aac58a7ceca2da0e38e90a72 -- ssh://hgssh/testrepo
+    > pulling from ssh://hgssh/testrepo
+    > adding changesets
+    > adding manifests
+    > adding file changes
+    > added 1 changesets with 1 changes to 1 files
+    > added 1 pushes
+    > updating moz-owner file
+    > new changesets 77538e1ce4be
+    > (run 'hg update' to get a working copy)
+    [0]
+  pulled 1 changesets into /repo/hg/mozilla/testrepo
+  pulling 1 heads (89e594ce6b790e64021edfe272c70db75e7304ab) and 1 nodes from ssh://hgssh/mozilla-central into /repo/hg/mozilla/mozilla-central
+    $ /var/hg/venv_replication/bin/hg pull -r89e594ce6b790e64021edfe272c70db75e7304ab -- ssh://hgssh/mozilla-central
+    > pulling from ssh://hgssh/mozilla-central
+    > searching for changes
+    > adding changesets
+    > adding manifests
+    > adding file changes
+    > added 1 changesets with 1 changes to 1 files
+    > received pushlog entry for unknown changeset ba17b5c8e955a5e7f57c478cdd75bc999c5460a1; ignoring
+    > added 1 pushes
+    > new changesets 89e594ce6b79
+    > (run 'hg update' to get a working copy)
+    [0]
+  pulled 1 changesets into /repo/hg/mozilla/mozilla-central
+
+Verify bootstrap log is correct
+
+  $ hgmo exec hgweb0 cat /var/log/vcsrbootstrap/bootstrap.log
+  * * vcsreplicator.bootstrap reading hgssh JSON document (glob)
+  * * vcsreplicator.bootstrap JSON document read (glob)
+  * * vcsreplicator.bootstrap assigning the consumer to partition 0 (glob)
+  * * vcsreplicator.bootstrap seeking the consumer to offset 6 (glob)
+  * * vcsreplicator.bootstrap partition 0 of topic pushdata moved to offset 6 (glob)
+  * * vcsreplicator.bootstrap message on partition 0, offset 6 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 0, offset 7 has been collected (glob)
+  * * vcsreplicator.bootstrap finished retrieving messages on partition 0 (glob)
+  * * vcsreplicator.bootstrap assigning the consumer to partition 2 (glob)
+  * * vcsreplicator.bootstrap seeking the consumer to offset 10 (glob)
+  * * vcsreplicator.bootstrap partition 2 of topic pushdata moved to offset 10 (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 10 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 11 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 12 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 13 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 14 has been collected (glob)
+  * * vcsreplicator.bootstrap message on partition 2, offset 15 has been collected (glob)
+  * * vcsreplicator.bootstrap finished retrieving messages on partition 2 (glob)
+  * * vcsreplicator.bootstrap finished retrieving messages from Kafka (glob)
+  * * vcsreplicator.bootstrap processing messages for partition 0 (glob)
+  * * vcsreplicator.bootstrap scheduled clone for {moz}/deleterepo (glob)
+  * * vcsreplicator.bootstrap syncing repo: {moz}/deleterepo (glob)
+  * * vcsreplicator.bootstrap processing messages for partition 2 (glob)
+  * * vcsreplicator.bootstrap scheduled clone for {moz}/mozilla-central (glob)
+  * * vcsreplicator.bootstrap scheduled clone for {moz}/testrepo (glob)
+  * * vcsreplicator.bootstrap extra messages found for {moz}/mozilla-central: 1 total (glob)
+  * * vcsreplicator.bootstrap extra messages found for {moz}/mozilla-central: 2 total (glob)
+  * * vcsreplicator.bootstrap exiting sync for: {moz}/deleterepo (glob)
+  * * vcsreplicator.bootstrap syncing repo: {moz}/mozilla-central (glob)
+  * * vcsreplicator.bootstrap error triggering replication of Mercurial repo {moz}/deleterepo: (255, "pulling from ssh://hgssh/deleterepo\nremote: Warning: Permanently added the RSA host key for IP address * to the list of known hosts.\nremote: requested repo deleterepo does not exist", 'abort: no suitable response from remote hg!') (glob)
+  * * vcsreplicator.bootstrap 2 repositories remaining (glob)
+  * * vcsreplicator.bootstrap exiting sync for: {moz}/mozilla-central (glob)
+  * * vcsreplicator.bootstrap syncing repo: {moz}/testrepo (glob)
+  * * vcsreplicator.bootstrap {moz}/mozilla-central successfully cloned (glob)
+  * * vcsreplicator.bootstrap 1 repositories remaining (glob)
+  * * vcsreplicator.bootstrap scheduling extra processing for {moz}/mozilla-central (glob)
+  * * vcsreplicator.bootstrap exiting sync for: {moz}/testrepo (glob)
+  * * vcsreplicator.bootstrap {moz}/testrepo successfully cloned (glob)
+  * * vcsreplicator.bootstrap 0 repositories remaining (glob)
+  * * vcsreplicator.bootstrap extra processing for {moz}/mozilla-central completed successfully (glob)
+  * * vcsreplicator.bootstrap 0 batches remaining (glob)
+  * bootstrap process complete (glob)
 
 Print offsets for vcsreplicator after full bootstrap and vcsreplicator daemons activated.
 
   $ hgmo exec hgweb0 /var/hg/venv_replication/bin/vcsreplicator-consumer /etc/mercurial/vcsreplicator.ini --wait-for-no-lag
   $ hgmo exec hgweb0 /var/hg/venv_replication/bin/vcsreplicator-print-offsets /etc/mercurial/vcsreplicator.ini
   topic     group           partition    offset    available    lag (s)
   --------  ------------  -----------  --------  -----------  ---------
   pushdata  *            0         8            8          0 (glob)
--- a/pylib/vcsreplicator/vcsreplicator/bootstrap.py
+++ b/pylib/vcsreplicator/vcsreplicator/bootstrap.py
@@ -27,22 +27,38 @@ from .consumer import (
     process_hg_sync,
     handle_message_main,
     MAX_BUFFER_SIZE,
 )
 
 
 REPOS_DIR = '/repo/hg/mozilla'
 
-logger = logging.getLogger('vcsreplicator.bootstrap')
+formatter = logging.Formatter('%(asctime)s %(name)s %(message)s', datefmt='%Y-%m-%d %H:%M:%S')
+formatter.converter = time.gmtime
 
-# Quiet down the vcsreplicator.consumer logger when these scripts are running
+logger = logging.getLogger('vcsreplicator.bootstrap')
+main_file_handler = logging.FileHandler('/var/log/vcsrbootstrap/bootstrap.log')
+main_file_handler.setFormatter(formatter)
+main_stdout_handler = logging.StreamHandler(sys.stdout)
+main_stdout_handler.setFormatter(formatter)
+logger.addHandler(main_file_handler)
+logger.addHandler(main_stdout_handler)
+logger.setLevel(logging.INFO)
+
+# Send vcsreplicator consumer logs to a separate file
 consumer_logger = logging.getLogger('vcsreplicator.consumer')
-null_handler = logging.FileHandler('/dev/null')
-consumer_logger.addHandler(null_handler)
+consumer_handler = logging.FileHandler('/var/log/vcsrbootstrap/consumer.log')
+consumer_logger.addHandler(consumer_handler)
+
+# Send kafka-python logs to a separate file
+kafka_logger = logging.getLogger('kafka')
+kafka_handler = logging.FileHandler('/var/log/vcsrbootstrap/kafka.log')
+kafka_handler.setLevel(logging.DEBUG)
+kafka_logger.addHandler(kafka_handler)
 
 
 def clone_repo(config, path, requirements, hgrc, heads):
     """Wraps process_hg_sync to provide logging"""
     logger.info('syncing repo: %s' % path)
     try:
         return process_hg_sync(config, path, requirements, hgrc, heads, create=True)
     finally:
@@ -145,25 +161,16 @@ def hgssh():
 
 
 def hgweb():
     '''hgweb component of the vcsreplicator bootstrap procedure. Takes a
     vcsreplicator config path on the CLI and takes a JSON data structure
     on stdin'''
     import argparse
 
-    # Configure logging
-    logger.setLevel(logging.INFO)
-    handler = logging.StreamHandler(sys.stdout)
-    handler.setLevel(logging.INFO)
-    formatter = logging.Formatter('%(name)s %(message)s')
-    formatter.converter = time.gmtime
-    handler.setFormatter(formatter)
-    logger.addHandler(handler)
-
     # Parse CLI args
     parser = argparse.ArgumentParser()
     parser.add_argument('config', help='Path of config file to load')
     parser.add_argument('input', help='JSON data input (output from the hgssh bootstrap procedure) file path')
     parser.add_argument('--workers', help='Number of concurrent workers to use for performing clones', type=int,
                         default=multiprocessing.cpu_count())
     args = parser.parse_args()