sg-replicate race log

gistfile1.txt

12:44 $ go1.10rc1 build -race && ./sync_gateway config.json
2018-02-01T12:44:45.009Z Enabling logging: [*]
2018-02-01T12:44:45.009Z ==== /() ====
2018-02-01T12:44:45.009Z Configured process to allow 5000 open file descriptors
2018-02-01T12:44:45.009Z Opening db /db1 as bucket "db1", pool "default", server <http://127.0.0.1:8091>
2018-02-01T12:44:45.010Z GoCBCustomSGTranscoder Opening Couchbase database db1 on <http://127.0.0.1:8091> as user "Administrator"
2018-02-01T12:44:45.024Z Design docs for current SG view version (2.0) found.
2018-02-01T12:44:45.024Z Verifying view availability for bucket db1...
2018-02-01T12:44:45.029Z Views ready for bucket db1.
2018-02-01T12:44:45.029Z Cache: Initializing changes cache with options {ChannelCacheOptions:{ChannelCacheMinLength:0 ChannelCacheMaxLength:0 ChannelCacheAge:0s} CachePendingSeqMaxWait:5s CachePendingSeqMaxNum:10000 CacheSkippedSeqMaxWait:1h0m0s}
2018-02-01T12:44:45.029Z Initializing changes cache for database db1 with sequence: 1
2018-02-01T12:44:45.030Z Feed: Starting mutation feed on bucket db1 due to either channel cache mode or doc tracking (auto-import/bucketshadow)
2018-02-01T12:44:45.030Z Feed: Using DCP feed for bucket: "db1" (based on feed_type specified in config file)
2018-02-01T12:44:45.034Z Feed+: Initializing DCP with no backfill - seeding seqnos: map[0:2 32:1 8:1]
2018-02-01T12:44:45.039Z Feed+: Initializing DCP with no backfill - seeding seqnos: map[8:1 32:1 0:2]
2018-02-01T12:44:45.039Z Feed+: Connecting to new bucket datasource.  URLs:[http://127.0.0.1:8091], pool:default, bucket:db1
2018-02-01T12:44:45.042Z Using default sync function 'channel(doc.channels)' for database "db1"
2018-02-01T12:44:45.043Z     Reset guest user to config
2018-02-01T12:44:45.043Z Opening db /db2 as bucket "db2", pool "default", server <http://127.0.0.1:8091>
2018-02-01T12:44:45.044Z GoCBCustomSGTranscoder Opening Couchbase database db2 on <http://127.0.0.1:8091> as user "Administrator"
2018-02-01T12:44:45.059Z Design docs for current SG view version (2.0) found.
2018-02-01T12:44:45.059Z Verifying view availability for bucket db2...
_time=2018-02-01T12:44:45.060+00:00 _level=INFO _msg=Using plain authentication for user Administrator
2018-02-01T12:44:45.064Z Views ready for bucket db2.
2018-02-01T12:44:45.065Z Cache: Initializing changes cache with options {ChannelCacheOptions:{ChannelCacheMinLength:0 ChannelCacheMaxLength:0 ChannelCacheAge:0s} CachePendingSeqMaxWait:5s CachePendingSeqMaxNum:10000 CacheSkippedSeqMaxWait:1h0m0s}
2018-02-01T12:44:45.065Z Initializing changes cache for database db2 with sequence: 1
2018-02-01T12:44:45.065Z Feed: Starting mutation feed on bucket db2 due to either channel cache mode or doc tracking (auto-import/bucketshadow)
2018-02-01T12:44:45.065Z Feed: Using DCP feed for bucket: "db2" (based on feed_type specified in config file)
2018-02-01T12:44:45.070Z Feed+: Initializing DCP with no backfill - seeding seqnos: map[8:1 32:1 0:2]
2018-02-01T12:44:45.074Z Feed+: Initializing DCP with no backfill - seeding seqnos: map[0:2 8:1 32:1]
2018-02-01T12:44:45.074Z Feed+: Connecting to new bucket datasource.  URLs:[http://127.0.0.1:8091], pool:default, bucket:db2
2018-02-01T12:44:45.075Z Using default sync function 'channel(doc.channels)' for database "db2"
2018-02-01T12:44:45.076Z     Reset guest user to config
2018-02-01T12:44:45.076Z Starting admin server on 127.0.0.1:4985
2018-02-01T12:44:45.077Z Debug: RetryLoop retrying GET http://127.0.0.1:4985/ after 100 ms.
_time=2018-02-01T12:44:45.087+00:00 _level=INFO _msg=Using plain authentication for user Administrator
2018-02-01T12:44:45.092Z Starting server on :4984 ...
2018-02-01T12:44:45.183Z HTTP:  #001: GET / (as ADMIN)
2018-02-01T12:44:45.183Z HTTP+: #001:     --> 200   (0.4 ms)
2018-02-01T12:44:45.189Z HTTP:  #002: GET /
2018-02-01T12:44:45.190Z HTTP+: #002:     --> 200   (0.2 ms)
2018-02-01T12:44:45.190Z Replicate: Starting replication with parameters {ReplicationId:C1_C2_2900e20bd52acb546551a8d1abc8f0eb Source:http://127.0.0.1:4985 SourceDb:db1 Channels:[SGREP_1] Target:http://127.0.0.1:4985 TargetDb:db2 ChangesFeedLimit:100 Lifecycle:0 Disabled:false Async:true}
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] stateFnPreStarted got event: {REPLICATION_START <nil>}
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] stateFnPreStarted got START event: {REPLICATION_START <nil>}
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] sent notificication: &{REPLICATION_ACTIVE <nil> <nil>}
==================
WARNING: DATA RACE
Read at 0x00c420460070 by goroutine 116:
  github.com/couchbaselabs/sg-replicate.stateFnPreStarted()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbaselabs/sg-replicate/replication_state.go:20 +0x57d
  github.com/couchbaselabs/sg-replicate.stateFnPreStarted()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbaselabs/sg-replicate/replication_state.go:18 +0x563
  github.com/couchbaselabs/sg-replicate.(*Replication).processEvents()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbaselabs/sg-replicate/synctube.go:120 +0x151

Previous write at 0x00c420460070 by goroutine 115:
  sync/atomic.AddInt32()
      /Users/benbrooks/sdk/go1.10rc1/src/runtime/race_amd64.s:269 +0xb
  sync.(*Mutex).Unlock()
      /Users/benbrooks/sdk/go1.10rc1/src/sync/mutex.go:182 +0x54
  github.com/couchbaselabs/sg-replicate.(*Replication).GetStats()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbaselabs/sg-replicate/synctube.go:80 +0xc9
  github.com/couchbase/sync_gateway/base.(*Replicator).populateActiveTaskFromReplication()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbase/sync_gateway/base/replicator.go:228 +0x79
  github.com/couchbase/sync_gateway/base.(*Replicator).Replicate()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbase/sync_gateway/base/replicator.go:58 +0x2d0
  github.com/couchbase/sync_gateway/rest.(*ServerContext).startReplicators.func1()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbase/sync_gateway/rest/server_context.go:114 +0x8e

Goroutine 116 (running) created at:
  github.com/couchbaselabs/sg-replicate.NewReplication()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbaselabs/sg-replicate/synctube.go:61 +0x17b
  github.com/couchbaselabs/sg-replicate.StartOneShotReplication()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbaselabs/sg-replicate/synctube.go:93 +0x88
  github.com/couchbase/sync_gateway/base.(*Replicator).startOneShotReplication()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbase/sync_gateway/base/replicator.go:174 +0x62
  github.com/couchbase/sync_gateway/base.(*Replicator).startReplication()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbase/sync_gateway/base/replicator.go:146 +0x2d7
  github.com/couchbase/sync_gateway/base.(*Replicator).Replicate()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbase/sync_gateway/base/replicator.go:56 +0x268
  github.com/couchbase/sync_gateway/rest.(*ServerContext).startReplicators.func1()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbase/sync_gateway/rest/server_context.go:114 +0x8e

Goroutine 115 (running) created at:
  github.com/couchbase/sync_gateway/rest.(*ServerContext).startReplicators()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbase/sync_gateway/rest/server_context.go:113 +0x30e
  github.com/couchbase/sync_gateway/rest.(*ServerContext).PostStartup()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbase/sync_gateway/rest/server_context.go:92 +0x38
  github.com/couchbase/sync_gateway/rest.RunServer.func2()
      /Users/benbrooks/dev/sync_gateway/master/godeps/src/github.com/couchbase/sync_gateway/rest/config.go:803 +0x1cb
==================
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] Transition from stateFnActiveFetchCheckpoint -> stateFnActive
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] new state: 0x1733490
2018-02-01T12:44:45.203Z HTTP:  #003: GET /db2/_local/81b5cb5fc937b7bd8d552ed5ee75a863aab37f3f (as ADMIN)
2018-02-01T12:44:45.203Z HTTP: #003:     --> 404 missing  (0.5 ms)
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] resp: &{404 Not Found 404 HTTP/1.1 1 1 map[Content-Type:[application/json] Server:[/2.0 branch/ commit/] Date:[Thu, 01 Feb 2018 12:44:45 GMT] Content-Length:[40]] 0xc4202ea340 40 [] false false map[] 0xc4202de000 <nil>}, err: <nil>
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] 404 trying to get checkpoint, continue..
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] stateFnActiveFetchCheckpoint got event: {FETCH_CHECKPOINT_SUCCEEDED {0  }}
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] call fetchChangesFeed()
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] Transition from stateFnActiveFetchCheckpoint -> stateFnActiveFetchChangesFeed
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] new state: 0x17340e0
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] stateFnActiveFetchChangesFeed
2018/02/01 12:44:45 Replicate: sequenceNumberToString called with: 0 type: int
2018/02/01 12:44:45 Replicate: sequence is an int
2018/02/01 12:44:45 Replicate: sequenceNumberToString called with: 0 type: int
2018/02/01 12:44:45 Replicate: sequence is an int
2018-02-01T12:44:45.205Z HTTP:  #004: GET /db1/_changes?feed=normal&limit=100&heartbeat=30000&style=all_docs&since=0&filter=sync_gateway/bychannel&channels=SGREP_1 (as ADMIN)
2018-02-01T12:44:45.213Z Changes+: Int sequence multi changes feed...
2018-02-01T12:44:45.213Z Changes: MultiChangesFeed(channels: {SGREP_1}, options: {Since:0 Limit:100 Conflicts:true IncludeDocs:false Wait:false Continuous:false Terminator:0xc4202b8a20 HeartbeatMs:30000 TimeoutMs:300000 ActiveOnly:false}) ...
2018-02-01T12:44:45.214Z Changes+: MultiChangesFeed: channels expand to "" ...
2018-02-01T12:44:45.216Z Cache: Initialized cache for channel "SGREP_1" with options: &{ChannelCacheMinLength:50 ChannelCacheMaxLength:500 ChannelCacheAge:1m0s}
2018-02-01T12:44:45.216Z Cache: getCachedChanges("SGREP_1", 0) --> 0 changes valid from #2
2018-02-01T12:44:45.216Z Cache:   Querying 'channels' view for "SGREP_1" (start=#1, end=#2, limit=100)
2018-02-01T12:44:45.219Z Cache:     Got no rows from view for "SGREP_1"
2018-02-01T12:44:45.219Z Cache: GetChangesInChannel("SGREP_1") --> 0 rows
2018-02-01T12:44:45.219Z Changes+: [changesFeed] Found 0 changes for channel SGREP_1
2018-02-01T12:44:45.219Z Changes: MultiChangesFeed done
2018-02-01T12:44:45.219Z HTTP+: #004:     --> 200 OK  (14.1 ms)
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] changes feed resp: &{200 OK 200 HTTP/1.1 1 1 map[Content-Type:[application/json] Server:[/2.0 branch/ commit/] Date:[Thu, 01 Feb 2018 12:44:45 GMT] Cache-Control:[private, max-age=0, no-cache, no-store]] 0xc420556100 -1 [] false true map[] 0xc42017ac00 <nil>}, err: <nil>
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] event: &{FETCH_CHANGES_FEED_SUCCEEDED {[] 0}}
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] stateFnActiveFetchChangesFeed got event: {FETCH_CHANGES_FEED_SUCCEEDED {[] 0}}
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] new state: <nil>
2018/02/01 12:44:45 Replicate: [C1_C2_2900e20bd52acb546551a8d1abc8f0eb] processEvents() is done