gistfile1.txt

docker run -it -p 14984:4984 -p 14985: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:43:31.943Z [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:43:31.943Z ==== Couchbase Sync Gateway/HEAD(nobranch)(1e80aa4) ====
2018-05-23T21:43:31.943Z [INF] Console LogKeys: [* HTTP]
2018-05-23T21:43:31.943Z [INF] Console LogLevel: info
2018-05-23T21:43:31.943Z [INF] Log Redaction Level: none
2018-05-23T21:43:31.943Z [INF] requestedSoftFDLimit < currentSoftFdLimit (5000 < 1048576) no action needed
2018-05-23T21:43:31.943Z [INF] Opening db /db as bucket "default", pool "default", server <http://couchbase:8091>
2018-05-23T21:43:31.944Z [INF] GoCBCustomSGTranscoder Opening Couchbase database default on <http://couchbase:8091> as user "Administrator"
2018-05-23T21:43:31.944Z [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:43:31.951Z [INF] Successfully opened bucket
2018-05-23T21:43:31.957Z [INF] Initializing indexes with numReplicas: 0...
2018-05-23T21:43:32.048Z [INF] Verifying index availability for bucket default...
2018-05-23T21:43:32.058Z [INF] Indexes ready for bucket default.
2018-05-23T21:43:32.058Z [INF] Cache: Initializing changes cache with options {ChannelCacheOptions:{ChannelCacheMinLength:0 ChannelCacheMaxLength:0 ChannelCacheAge:0s} CachePendingSeqMaxWait:5s CachePendingSeqMaxNum:10000 CacheSkippedSeqMaxWait:1h0m0s}
2018-05-23T21:43:32.059Z [INF] Initializing changes cache for database db with sequence: 2
2018-05-23T21:43:32.059Z [INF] Got last seq: 2. Sleeping for a while
2018-05-23T21:44:32.059Z [INF] Done sleeping.
2018-05-23T21:44:32.059Z [INF] DCP: Starting mutation feed on bucket default due to either channel cache mode or doc tracking (auto-import/bucketshadow)
2018-05-23T21:44:32.059Z [INF] DCP: Using DCP feed for bucket: "default" (based on feed_type specified in config file)
2018-05-23T21:44:32.160Z [INF] Using default sync function 'channel(doc.channels)' for database "db"
2018-05-23T21:44:32.161Z [INF]     Reset guest user to config
2018-05-23T21:44:32.172Z [INF] Access: Computed channels for "testuser": !:1,testuser:2
2018-05-23T21:44:32.173Z [INF] Starting admin server on 127.0.0.1:4985
2018-05-23T21:44:32.180Z [INF] Starting server on :4984 ...
2018-05-23T21:44:32.193+00:00 [INFO] Using plain authentication for user <ud>Administrator</ud>
2018-05-23T21:51:26.011Z [INF] HTTP auth failed for username="foo"
2018-05-23T21:51:26.011Z [INF] HTTP:  #001: POST /db/
2018-05-23T21:51:26.011Z [INF] HTTP: #001:     --> 401 Invalid login  (0.8 ms)
2018-05-23T21:52:18.358Z [INF] HTTP:  #002: POST /db/ (as testuser)
2018-05-23T21:52:18.360Z [INF] CRUD: 	Doc "d0d7680140e8aba3d303e5d3d475fb1c" in channels "{testuser}"
2018-05-23T21:52:18.361Z [INF] CRUD: Stored doc "d0d7680140e8aba3d303e5d3d475fb1c" / "1-5eb803e4848d3235a5f60e061b637541"
2018-05-23T21:52:18.361Z [INF] HTTP+: #002:     --> 200   (77.4 ms)
2018-05-23T21:52:18.362Z [INF] Cache: Received #3 after   1ms ("d0d7680140e8aba3d303e5d3d475fb1c" / "1-5eb803e4848d3235a5f60e061b637541")
2018-05-23T21:52:18.362Z [INF] Cache: Initialized cache for channel "testuser" with options: &{ChannelCacheMinLength:50 ChannelCacheMaxLength:500 ChannelCacheAge:1m0s}
2018-05-23T21:52:18.362Z [INF] Cache:     #3 ==> channel "testuser"
2018-05-23T21:52:18.362Z [INF] Cache: Initialized cache for channel "*" with options: &{ChannelCacheMinLength:50 ChannelCacheMaxLength:500 ChannelCacheAge:1m0s}
2018-05-23T21:52:18.362Z [INF] Cache:     #3 ==> channel "*"
2018-05-23T21:53:06.084Z [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-23T21:53:06.084Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc4201cc9c0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T21:53:06.085Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 1 changes valid from #3
2018-05-23T21:53:06.087Z [INF] Cache:   Querying 'channels' view for "testuser" (start=#1, end=#3, limit=1000)
2018-05-23T21:53:06.162Z [INF] Cache:     Got 1 rows from query for "testuser": #3 ... #3
2018-05-23T21:53:06.162Z [INF] Cache: GetChangesInChannel("testuser") --> 1 rows
2018-05-23T21:53:06.162Z [INF] Cache: Initialized cache for channel "!" with options: &{ChannelCacheMinLength:50 ChannelCacheMaxLength:500 ChannelCacheAge:1m0s}
2018-05-23T21:53:06.162Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #3
2018-05-23T21:53:06.162Z [INF] Cache:   Querying 'channels' view for "!" (start=#1, end=#3, limit=1000)
2018-05-23T21:53:06.165Z [INF] Cache:     Got no rows from query for channel:"!"
2018-05-23T21:53:06.165Z [INF] Cache: GetChangesInChannel("!") --> 0 rows
2018-05-23T21:53:06.165Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T21:53:06.166Z [INF] HTTP+: #003:     --> 200 OK  (81.9 ms)
2018-05-23T21:54:19.171Z [INF] HTTP:  #004: POST /db/ (as testuser)
2018-05-23T21:54:19.173Z [INF] CRUD: 	Doc "5b3ce61b0b75b4519725ae798a052f0b" in channels "{testuser}"
2018-05-23T21:54:19.174Z [INF] CRUD: Stored doc "5b3ce61b0b75b4519725ae798a052f0b" / "1-5eb803e4848d3235a5f60e061b637541"
2018-05-23T21:54:19.174Z [INF] HTTP+: #004:     --> 200   (3.2 ms)
2018-05-23T21:54:19.175Z [INF] Cache: Received #4 after   2ms ("5b3ce61b0b75b4519725ae798a052f0b" / "1-5eb803e4848d3235a5f60e061b637541")
2018-05-23T21:54:19.175Z [INF] Cache:     #4 ==> channel "testuser"
2018-05-23T21:54:19.175Z [INF] Cache:     #4 ==> channel "*"
2018-05-23T21:54:23.550Z [INF] HTTP:  #005: POST /db/ (as testuser)
2018-05-23T21:54:23.551Z [INF] CRUD: 	Doc "720c216780bebd007935eae97094c867" in channels "{testuser}"
2018-05-23T21:54:23.552Z [INF] CRUD: Stored doc "720c216780bebd007935eae97094c867" / "1-5eb803e4848d3235a5f60e061b637541"
2018-05-23T21:54:23.553Z [INF] HTTP+: #005:     --> 200   (3.2 ms)
2018-05-23T21:54:23.553Z [INF] Cache: Received #5 after   2ms ("720c216780bebd007935eae97094c867" / "1-5eb803e4848d3235a5f60e061b637541")
2018-05-23T21:54:23.554Z [INF] Cache:     #5 ==> channel "testuser"
2018-05-23T21:54:23.554Z [INF] Cache:     #5 ==> channel "*"
2018-05-23T21:54:26.209Z [INF] HTTP:  #006: POST /db/ (as testuser)
2018-05-23T21:54:26.211Z [INF] CRUD: 	Doc "07ef5406314287d74ee2d27c87c0030d" in channels "{testuser}"
2018-05-23T21:54:26.211Z [INF] CRUD: Stored doc "07ef5406314287d74ee2d27c87c0030d" / "1-5eb803e4848d3235a5f60e061b637541"
2018-05-23T21:54:26.212Z [INF] HTTP+: #006:     --> 200   (3.0 ms)
2018-05-23T21:54:26.212Z [INF] Cache: Received #6 after   1ms ("07ef5406314287d74ee2d27c87c0030d" / "1-5eb803e4848d3235a5f60e061b637541")
2018-05-23T21:54:26.212Z [INF] Cache:     #6 ==> channel "testuser"
2018-05-23T21:54:26.212Z [INF] Cache:     #6 ==> channel "*"
2018-05-23T21:54:27.788Z [INF] HTTP:  #007: POST /db/ (as testuser)
2018-05-23T21:54:27.789Z [INF] CRUD: 	Doc "4a9eb5d3958fcce44b9d254121c89b76" in channels "{testuser}"
2018-05-23T21:54:27.790Z [INF] CRUD: Stored doc "4a9eb5d3958fcce44b9d254121c89b76" / "1-5eb803e4848d3235a5f60e061b637541"
2018-05-23T21:54:27.790Z [INF] HTTP+: #007:     --> 200   (2.4 ms)
2018-05-23T21:54:27.796Z [INF] Cache: Received #7 after   6ms ("4a9eb5d3958fcce44b9d254121c89b76" / "1-5eb803e4848d3235a5f60e061b637541")
2018-05-23T21:54:27.796Z [INF] Cache:     #7 ==> channel "testuser"
2018-05-23T21:54:27.796Z [INF] Cache:     #7 ==> channel "*"
2018-05-23T21:55:31.419Z [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-23T21:55:31.419Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc42028c060 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T21:55:31.420Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T21:55:31.421Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 5 changes valid from #1
2018-05-23T21:55:31.422Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T21:55:31.422Z [INF] HTTP+: #008:     --> 200 OK  (3.5 ms)
2018-05-23T22:03:35.433Z [INF] HTTP:  #009: 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:03:35.433Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc4200124e0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T22:03:35.434Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T22:03:35.434Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 5 changes valid from #1
2018-05-23T22:03:35.434Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T22:03:35.434Z [INF] HTTP+: #009:     --> 200 OK  (2.2 ms)



2018-05-23T22:47:14.884Z [INF] HTTP:  #010: 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:14.884Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc42028cea0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T22:47:14.886Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T22:47:14.886Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 5 changes valid from #1
2018-05-23T22:47:14.886Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T22:47:14.887Z [INF] HTTP+: #010:     --> 200 OK  (3.9 ms)
2018-05-23T22:47:22.875Z [INF] HTTP:  #011: POST /db/ (as testuser)
2018-05-23T22:47:22.887Z [INF] CRUD: 	Doc "b05d8b1597c276ae43033f40ff5c1bef" in channels "{testuser}"
2018-05-23T22:47:22.900Z [INF] CRUD: Stored doc "b05d8b1597c276ae43033f40ff5c1bef" / "1-5eb803e4848d3235a5f60e061b637541"
2018-05-23T22:47:22.900Z [INF] HTTP+: #011:     --> 200   (26.0 ms)
2018-05-23T22:47:22.906Z [INF] Cache: Received #8 after  17ms ("b05d8b1597c276ae43033f40ff5c1bef" / "1-5eb803e4848d3235a5f60e061b637541")
2018-05-23T22:47:22.906Z [INF] Cache:     #8 ==> channel "testuser"
2018-05-23T22:47:22.906Z [INF] Cache:     #8 ==> channel "*"
2018-05-23T22:47:29.313Z [INF] HTTP:  #012: 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:29.313Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc420012a20 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T22:47:29.313Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 6 changes valid from #1
2018-05-23T22:47:29.313Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T22:47:29.313Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T22:47:29.313Z [INF] HTTP+: #012:     --> 200 OK  (1.1 ms)
2018-05-23T22:49:40.796Z [INF] HTTP:  #013: 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:49:40.797Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc42028cc60 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T22:49:40.798Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T22:49:40.798Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 6 changes valid from #1
2018-05-23T22:49:40.798Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T22:49:40.799Z [INF] HTTP+: #013:     --> 200 OK  (3.2 ms)
2018-05-23T23:45:45.202Z [INF] HTTP:  #014: 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:45.205Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc42011cf60 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T23:45:45.209Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T23:45:45.209Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 6 changes valid from #1
2018-05-23T23:45:45.211Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T23:45:45.212Z [INF] HTTP+: #014:     --> 200 OK  (14.1 ms)
2018-05-23T23:59:34.619Z [INF] HTTP:  #015: 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:34.620Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc420012cc0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-23T23:59:34.622Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-23T23:59:34.622Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 6 changes valid from #1
2018-05-23T23:59:34.622Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-23T23:59:34.622Z [INF] HTTP+: #015:     --> 200 OK  (4.7 ms)
2018-05-24T00:00:01.299Z [INF] HTTP:  #016: 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:01.299Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:1000 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc42011dbc0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...   (to testuser)
2018-05-24T00:00:01.300Z [INF] Cache: getCachedChanges("!", 0) --> 0 changes valid from #1
2018-05-24T00:00:01.300Z [INF] Cache: getCachedChanges("testuser", 2:0) --> 6 changes valid from #1
2018-05-24T00:00:01.301Z [INF] Changes: MultiChangesFeed done   (to testuser)
2018-05-24T00:00:01.302Z [INF] HTTP+: #016:     --> 200 OK  (3.8 ms)