gistfile1.txt

ocker run -it -p 24984:4984 -p 24985:4985 --network cb --volume /Users/tleyden/tmp/sg-docker:/tmp/ tleyden5iwx/sync_gateway:feature_issue_3558_int_cache_post_dcp sync_gateway /tmp/basic-couchbase-bucket.json
2018-05-23T21:54:09.204Z [ERR] No logFilePath configured, and --defaultLogFilePath flag is not set. Log files required for product support are not being generated. -- base.(*LoggingConfig).Init() at logging_config.go:40
2018-05-23T21:54:09.204Z ==== Couchbase Sync Gateway/HEAD(nobranch)(1e80aa4) ====
2018-05-23T21:54:09.204Z [INF] Console LogKeys: [* HTTP]
2018-05-23T21:54:09.204Z [INF] Console LogLevel: info
2018-05-23T21:54:09.204Z [INF] Log Redaction Level: none
2018-05-23T21:54:09.204Z [INF] requestedSoftFDLimit < currentSoftFdLimit (5000 < 1048576) no action needed
2018-05-23T21:54:09.204Z [INF] Opening db /db as bucket "default", pool "default", server <http://couchbase:8091>
2018-05-23T21:54:09.204Z [INF] GoCBCustomSGTranscoder Opening Couchbase database default on <http://couchbase:8091> as user "Administrator"
2018-05-23T21:54:09.205Z [INF] Auth: Attempting credential authentication http://couchbase:8091?http_idle_conn_timeout=90000&http_max_idle_conns=64000&http_max_idle_conns_per_host=256
2018-05-23T21:54:09.211Z [INF] Successfully opened bucket
2018-05-23T21:54:09.217Z [INF] Initializing indexes with numReplicas: 0...
2018-05-23T21:54:09.292Z [INF] Verifying index availability for bucket default...
2018-05-23T21:54:09.306Z [INF] Indexes ready for bucket default.
2018-05-23T21:54:09.307Z [INF] Cache: Initializing changes cache with options {ChannelCacheOptions:{ChannelCacheMinLength:0 ChannelCacheMaxLength:0 ChannelCacheAge:0s} CachePendingSeqMaxWait:5s CachePendingSeqMaxNum:10000 CacheSkippedSeqMaxWait:1h0m0s}
2018-05-23T21:54:09.307Z [INF] Initializing changes cache for database db with sequence: 3
2018-05-23T21:54:09.307Z [INF] Got last seq: 3. Sleeping for a while
2018-05-23T21:55:09.307Z [INF] Done sleeping.
2018-05-23T21:55:09.308Z [INF] DCP: Starting mutation feed on bucket default due to either channel cache mode or doc tracking (auto-import/bucketshadow)
2018-05-23T21:55:09.308Z [INF] DCP: Using DCP feed for bucket: "default" (based on feed_type specified in config file)
2018-05-23T21:55:09.402Z [INF] Using default sync function 'channel(doc.channels)' for database "db"
2018-05-23T21:55:09.403Z [INF]     Reset guest user to config
2018-05-23T21:55:09.403Z [INF] Starting admin server on 127.0.0.1:4985
2018-05-23T21:55:09.408Z [INF] Starting server on :4984 ...
2018-05-23T21:55:09.423+00:00 [INFO] Using plain authentication for user <ud>Administrator</ud>


2018-05-23T21:55:45.588Z [INF] HTTP:  #001: GET /db/_changes?limit=1000&style=main_only&active_only=false&include_docs=false&filter=&channels=testuser&doc_ids=[testdoc]&feed=normal&since=&heartbeat=0&timeout=300000 (as testuser)
2018-05-23T21:55:45.588Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc42011db00 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T21:55:45.588Z [INF] Cache: Initialized cache for channel "!" with options: &{ChannelCacheMinLength:50 ChannelCacheMaxLength:500 ChannelCacheAge:1m0s}
2018-05-23T21:55:45.588Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #4
2018-05-23T21:55:45.588Z [INF] Cache:   Querying 'channels' view for "!" (start=#1, end=#4, limit=1000)
2018-05-23T21:55:45.621Z [INF] Cache:     Got no rows from query for channel:"!"
2018-05-23T21:55:45.621Z [INF] Cache: GetChangesInChannel("!") --> 0 rows
2018-05-23T21:55:45.621Z [INF] Cache: Initialized cache for channel "testuser" with options: &{ChannelCacheMinLength:50 ChannelCacheMaxLength:500 ChannelCacheAge:1m0s}
2018-05-23T21:55:45.621Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 0 changes valid from #4
2018-05-23T21:55:45.621Z [INF] Cache:   Querying 'channels' view for "testuser" (start=#1, end=#4, limit=1000)
2018-05-23T21:55:45.627Z [INF] Cache:     Got 2 rows from query for "testuser": #3 ... #4
2018-05-23T21:55:45.627Z [INF] Cache:   Initialized cache of "testuser" with 2 entries from view (#3--#4)
2018-05-23T21:55:45.627Z [INF] Cache: GetChangesInChannel("testuser") --> 2 rows
2018-05-23T21:55:45.627Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T21:55:45.627Z [INF] HTTP+: #001:     --> 200 OK  (113.3 ms)
2018-05-23T21:55:49.276Z [INF] HTTP:  #002: GET /db/_changes?limit=1000&style=main_only&active_only=false&include_docs=false&filter=&channels=testuser&doc_ids=[testdoc]&feed=normal&since=&heartbeat=0&timeout=300000 (as testuser)
2018-05-23T21:55:49.276Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc420348d80 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T21:55:49.277Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T21:55:49.277Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 2 changes valid from #1
2018-05-23T21:55:49.277Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T21:55:49.277Z [INF] HTTP+: #002:     --> 200 OK  (1.2 ms)



2018-05-23T22:46:48.833Z [INF] HTTP:  #003: GET /db/_changes?limit=1000&style=main_only&active_only=false&include_docs=false&filter=&channels=testuser&doc_ids=[testdoc]&feed=normal&since=&heartbeat=0&timeout=300000 (as testuser)
2018-05-23T22:46:48.834Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc420013140 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T22:46:48.840Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T22:46:48.841Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 2 changes valid from #1
2018-05-23T22:46:48.841Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T22:46:48.841Z [INF] HTTP+: #003:     --> 200 OK  (13.9 ms)
2018-05-23T22:47:22.906Z [INF] Cache: Received #8 after  16ms ("b05d8b1597c276ae43033f40ff5c1bef" / "1-5eb803e4848d3235a5f60e061b637541")
2018-05-23T22:47:22.906Z [INF] Cache:   Deferring #8 (1 now waiting for #4...#7)
2018-05-23T22:47:30.108Z [INF] Cache:     #8 ==> channel "testuser"
2018-05-23T22:47:30.109Z [INF] Cache: Initialized cache for channel "*" with options: &{ChannelCacheMinLength:50 ChannelCacheMaxLength:500 ChannelCacheAge:1m0s}
2018-05-23T22:47:30.109Z [INF] Cache:     #8 ==> channel "*"
2018-05-23T22:47:44.048Z [INF] HTTP:  #004: GET /db/_changes?limit=1000&style=main_only&active_only=false&include_docs=false&filter=&channels=testuser&doc_ids=[testdoc]&feed=normal&since=&heartbeat=0&timeout=300000 (as testuser)
2018-05-23T22:47:44.048Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc4202680c0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T22:47:44.049Z [INF] Changes: get oldest, returning: 4
2018-05-23T22:47:44.049Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T22:47:44.049Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 3 changes valid from #1
2018-05-23T22:47:44.050Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T22:47:44.050Z [INF] HTTP+: #004:     --> 200 OK  (2.9 ms)
2018-05-23T23:45:58.036Z [INF] HTTP:  #005: GET /db/_changes?limit=1000&style=main_only&active_only=false&include_docs=false&filter=&channels=testuser&doc_ids=[testdoc]&feed=normal&since=&heartbeat=0&timeout=300000 (as testuser)
2018-05-23T23:45:58.036Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc42011c0c0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T23:45:58.036Z [INF] Changes: get oldest, returning: 4
2018-05-23T23:45:58.037Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 3 changes valid from #1
2018-05-23T23:45:58.037Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T23:45:58.037Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T23:45:58.038Z [INF] HTTP+: #005:     --> 200 OK  (2.1 ms)
2018-05-23T23:46:05.498Z [INF] HTTP:  #006: GET /db/_changes?limit=1000&style=main_only&active_only=false&include_docs=false&filter=&channels=testuser&doc_ids=[testdoc]&feed=normal&since=&heartbeat=0&timeout=300000 (as testuser)
2018-05-23T23:46:05.498Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc42011dda0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T23:46:05.498Z [INF] Changes: get oldest, returning: 4
2018-05-23T23:46:05.499Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 3 changes valid from #1
2018-05-23T23:46:05.499Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T23:46:05.499Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T23:46:05.499Z [INF] HTTP+: #006:     --> 200 OK  (2.2 ms)
2018-05-23T23:54:09.312Z [INF] Cache:   Querying 'channels' view for "*" (start=#4, end=#4, limit=0)
2018-05-23T23:54:09.405Z [INF] Cache:     Got 1 rows from query for "*": #4 ... #4
2018-05-23T23:54:09.405Z [INF] Cache:   Querying 'channels' view for "*" (start=#5, end=#5, limit=0)
2018-05-23T23:54:09.409Z [INF] Cache:     Got 1 rows from query for "*": #5 ... #5
2018-05-23T23:54:09.409Z [INF] Cache:   Querying 'channels' view for "*" (start=#6, end=#6, limit=0)
2018-05-23T23:54:09.413Z [INF] Cache:     Got 1 rows from query for "*": #6 ... #6
2018-05-23T23:54:09.413Z [INF] Cache:   Querying 'channels' view for "*" (start=#7, end=#7, limit=0)
2018-05-23T23:54:09.416Z [INF] Cache:     Got 1 rows from query for "*": #7 ... #7
2018-05-23T23:54:09.422Z [INF] Cache:   Received previously skipped out-of-order change (seq 4, expecting 9) doc "5b3ce61b0b75b4519725ae798a052f0b" / "1-5eb803e4848d3235a5f60e061b637541"
2018-05-23T23:54:09.422Z [INF] Changes: Acquired late sequence lock for 4
2018-05-23T23:54:09.423Z [INF] Cache:     #4 ==> channel "testuser"
2018-05-23T23:54:09.423Z [INF] Cache:     #4 ==> channel "*"
2018-05-23T23:54:09.423Z [INF] Cache:   Received previously skipped out-of-order change (seq 5, expecting 9) doc "720c216780bebd007935eae97094c867" / "1-5eb803e4848d3235a5f60e061b637541"
2018-05-23T23:54:09.424Z [INF] Changes: Acquired late sequence lock for 5
2018-05-23T23:54:09.424Z [INF] Cache:     #5 ==> channel "testuser"
2018-05-23T23:54:09.424Z [INF] Cache:     #5 ==> channel "*"
2018-05-23T23:54:09.424Z [INF] Cache:   Received previously skipped out-of-order change (seq 6, expecting 9) doc "07ef5406314287d74ee2d27c87c0030d" / "1-5eb803e4848d3235a5f60e061b637541"
2018-05-23T23:54:09.424Z [INF] Changes: Acquired late sequence lock for 6
2018-05-23T23:54:09.424Z [INF] Cache:     #6 ==> channel "testuser"
2018-05-23T23:54:09.424Z [INF] Cache:     #6 ==> channel "*"
2018-05-23T23:54:09.425Z [INF] Cache:   Received previously skipped out-of-order change (seq 7, expecting 9) doc "4a9eb5d3958fcce44b9d254121c89b76" / "1-5eb803e4848d3235a5f60e061b637541"
2018-05-23T23:54:09.425Z [INF] Changes: Acquired late sequence lock for 7
2018-05-23T23:54:09.425Z [INF] Cache:     #7 ==> channel "testuser"
2018-05-23T23:54:09.425Z [INF] Cache:     #7 ==> channel "*"
2018-05-23T23:54:09.425Z [WRN] Error purging skipped sequence 4 from skipped sequence queue -- db.(*changeCache).CleanSkippedSequenceQueue() at change_cache.go:286
2018-05-23T23:54:09.426Z [WRN] Error purging skipped sequence 5 from skipped sequence queue -- db.(*changeCache).CleanSkippedSequenceQueue() at change_cache.go:286
2018-05-23T23:54:09.426Z [WRN] Error purging skipped sequence 6 from skipped sequence queue -- db.(*changeCache).CleanSkippedSequenceQueue() at change_cache.go:286
2018-05-23T23:54:09.426Z [WRN] Error purging skipped sequence 7 from skipped sequence queue -- db.(*changeCache).CleanSkippedSequenceQueue() at change_cache.go:286
2018-05-23T23:59:44.183Z [INF] HTTP:  #007: GET /db/_changes?limit=1000&style=main_only&active_only=false&include_docs=false&filter=&channels=testuser&doc_ids=[testdoc]&feed=normal&since=&heartbeat=0&timeout=300000 (as testuser)
2018-05-23T23:59:44.183Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc4203369c0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T23:59:44.184Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T23:59:44.184Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 6 changes valid from #1
2018-05-23T23:59:44.184Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T23:59:44.187Z [INF] HTTP+: #007:     --> 200 OK  (5.0 ms)
2018-05-24T00:00:57.344Z [INF] HTTP:  #008: GET /db/_changes?limit=1000&style=main_only&active_only=false&include_docs=false&filter=&channels=testuser&doc_ids=[testdoc]&feed=normal&since=&heartbeat=0&timeout=300000 (as testuser)
2018-05-24T00:00:57.344Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc4202683c0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-24T00:00:57.346Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 6 changes valid from #1
2018-05-24T00:00:57.346Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-24T00:00:57.348Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-24T00:00:57.349Z [INF] HTTP+: #008:     --> 200 OK  (5.6 ms)