I deployed a function and the backlog is 44K. It seems nothing is happing, the backlog is not going down. What the best way to figure what the issue is?
I am using CB 6.6 Enterprise
Hi @dipen_patel,
There is no one reason that comes to my mind as a likely cause for this. So I’d need to look at log files. Can you please share your log files?
Thanks,
Siri
Here is some of the logs
2020-09-09T12:03:06.833+00:00 [Info] Consumer::processDCPEvents [worker_task_update_2:/tmp/127.0.0.1:8091_2_4223910612.sock:15245] vb: 598 got STREAMREQ status: ROLLBACK
2020-09-09T12:03:06.833+00:00 [Info] Consumer::processDCPEvents [worker_task_update_2:/tmp/127.0.0.1:8091_2_4223910612.sock:15245] vb: 598 STREAMREQ metadataUpdated: true
2020-09-09T12:03:06.833+00:00 [Trace] [gocb] Writing request. 127.0.0.1:37588 to 127.0.0.1:11210 OP=0xd1. Opaque=242451
2020-09-09T12:03:06.834+00:00 [Trace] [gocb] Resolving response OP=0x0. Opaque=242450
2020-09-09T12:03:06.834+00:00 [Trace] [gocb] Dispatching response callback. OP=0x0. Opaque=242450
2020-09-09T12:03:06.857+00:00 [Trace] [gocb] Resolving response OP=0xd1. Opaque=331587
2020-09-09T12:03:06.857+00:00 [Trace] [gocb] Dispatching response callback. OP=0xd1. Opaque=331587
2020-09-09T12:03:06.857+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 315 STREAMREQ Failed. Inserting entry: &consumer.vbFlogEntry{flog:(*memcached.FailoverLog)(nil), seqNo:0x0, signalStreamEnd:false, statusCode:0x23, streamReqRetry:true, vb:0x13b} to vbFlogChan
2020-09-09T12:03:06.857+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 381 got STREAMREQ status: ROLLBACK
2020-09-09T12:03:06.857+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 381 STREAMREQ metadataUpdated: true
2020-09-09T12:03:06.857+00:00 [Trace] [gocb] Writing request. 127.0.0.1:37580 to 127.0.0.1:11210 OP=0xd1. Opaque=331588
2020-09-09T12:03:06.858+00:00 [Info] Consumer::getKvNodesFromVbMap [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] Bucket: sync_gateway_sw1 kvNodes: [127.0.0.1:11210]
2020-09-09T12:03:06.861+00:00 [Trace] [gocb] Resolving response OP=0xd1. Opaque=331588
2020-09-09T12:03:06.861+00:00 [Trace] [gocb] Dispatching response callback. OP=0xd1. Opaque=331588
2020-09-09T12:03:06.861+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 381 STREAMREQ Failed. Inserting entry: &consumer.vbFlogEntry{flog:(*memcached.FailoverLog)(nil), seqNo:0x0, signalStreamEnd:false, statusCode:0x23, streamReqRetry:true, vb:0x17d} to vbFlogChan
2020-09-09T12:03:06.861+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 389 got STREAMREQ status: ROLLBACK
2020-09-09T12:03:06.861+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 389 STREAMREQ metadataUpdated: true
2020-09-09T12:03:06.861+00:00 [Trace] [gocb] Writing request. 127.0.0.1:37580 to 127.0.0.1:11210 OP=0xd1. Opaque=331589
:
, seqNo:0x0, signalStreamEnd:false, statusCode:0x23, streamReqRetry:true, vb:0x12a} to vbFlogChan
2020-09-09T12:03:06.820+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 315 got STREAMREQ status: ROLLBACK
2020-09-09T12:03:06.820+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 315 STREAMREQ metadataUpdated: true
2020-09-09T12:03:06.820+00:00 [Trace] [gocb] Writing request. 127.0.0.1:37580 to 127.0.0.1:11210 OP=0xd1. Opaque=331587
2020-09-09T12:03:06.821+00:00 [Info] Consumer::processDCPEvents [worker_task_update_2:/tmp/127.0.0.1:8091_2_4223910612.sock:15245] vb: 519 STREAMREQ metadataUpdated: true
2020-09-09T12:03:06.821+00:00 [Trace] [gocb] Writing request. 127.0.0.1:37588 to 127.0.0.1:11210 OP=0xd1. Opaque=242448
2020-09-09T12:03:06.826+00:00 [Trace] [gocb] Resolving response OP=0xd1. Opaque=242448
2020-09-09T12:03:06.826+00:00 [Trace] [gocb] Dispatching response callback. OP=0xd1. Opaque=242448
2020-09-09T12:03:06.826+00:00 [Info] Consumer::processDCPEvents [worker_task_update_2:/tmp/127.0.0.1:8091_2_4223910612.sock:15245] vb: 519 STREAMREQ Failed. Inserting entry: &consumer.vbFlogEntry{flog:(*memcached.FailoverLog)(nil), seqNo:0x0, signalStreamEnd:false, statusCode:0x23, streamReqRetry:true, vb:0x207} to vbFlogChan
2020-09-09T12:03:06.826+00:00 [Info] Consumer::processDCPEvents [worker_task_update_2:/tmp/127.0.0.1:8091_2_4223910612.sock:15245] vb: 520 got STREAMREQ status: ROLLBACK
2020-09-09T12:03:06.826+00:00 [Info] Consumer::processDCPEvents [worker_task_update_2:/tmp/127.0.0.1:8091_2_4223910612.sock:15245] vb: 520 STREAMREQ metadataUpdated: true
2020-09-09T12:03:06.826+00:00 [Trace] [gocb] Resolving response OP=0x0. Opaque=331586
2020-09-09T12:03:06.826+00:00 [Trace] [gocb] Dispatching response callback. OP=0x0. Opaque=331586
2020-09-09T12:03:06.826+00:00 [Trace] [gocb] Writing request. 127.0.0.1:37588 to 127.0.0.1:11210 OP=0xd1. Opaque=242449
2020-09-09T12:03:06.826+00:00 [Info] Consumer::handleFailoverLog [worker_task_update_2:/tmp/127.0.0.1:8091_2_4223910612.sock:15245] vb: 519 Got entry from vbFlogChan: &consumer.vbFlogEntry{flog:(*memcached.FailoverLog)(nil), seqNo:0x0, signalStreamEnd:false, statusCode:0x23, streamReqRetry:true, vb:0x207}
2020-09-09T12:03:06.826+00:00 [Info] Consumer::handleFailoverLog [worker_task_update_2:/tmp/127.0.0.1:8091_2_4223910612.sock:15245] vb: 519 purging entry from inflightDcpStreams
2020-09-09T12:03:06.826+00:00 [Trace] [gocb] Writing request. 127.0.0.1:37588 to 127.0.0.1:11210 OP=0x0. Opaque=242450
2020-09-09T12:03:06.833+00:00 [Trace] [gocb] Resolving response OP=0xd1. Opaque=242449
2020-09-09T12:03:06.833+00:00 [Trace] [gocb] Dispatching response callback. OP=0xd1. Opaque=242449
2020-09-09T12:03:06.833+00:00 [Info] Consumer::processDCPEvents [worker_task_update_2:/tmp/127.0.0.1:8091_2_4223910612.sock:15245] vb: 520 STREAMREQ Failed. Inserting entry: &consumer.vbFlogEntry{flog:(*memcached.FailoverLog)(nil), seqNo:0x0, signalStreamEnd:false, statusCode:0x23, streamReqRetry:true, vb:0x208} to vbFlogChan
2020-09-09T12:03:06.833+00:00 [Info] Consumer::processDCPEvents [worker_task_update_2:/tmp/127.0.0.1:8091_2_4223910612.sock:15245] vb: 598 got STREAMREQ status: ROLLBACK
2020-09-09T12:03:06.833+00:00 [Info] Consumer::processDCPEvents [worker_task_update_2:/tmp/127.0.0.1:8091_2_4223910612.sock:15245] vb: 598 STREAMREQ metadataUpdated: true
2020-09-09T12:03:06.833+00:00 [Trace] [gocb] Writing request. 127.0.0.1:37588 to 127.0.0.1:11210 OP=0xd1. Opaque=242451
2020-09-09T12:03:06.834+00:00 [Trace] [gocb] Resolving response OP=0x0. Opaque=242450
2020-09-09T12:03:06.834+00:00 [Trace] [gocb] Dispatching response callback. OP=0x0. Opaque=242450
2020-09-09T12:03:06.857+00:00 [Trace] [gocb] Resolving response OP=0xd1. Opaque=331587
2020-09-09T12:03:06.857+00:00 [Trace] [gocb] Dispatching response callback. OP=0xd1. Opaque=331587
2020-09-09T12:03:06.857+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 315 STREAMREQ Failed. Inserting entry: &consumer.vbFlogEntry{flog:(*memcached.FailoverLog)(nil), seqNo:0x0, signalStreamEnd:false, statusCode:0x23, streamReqRetry:true, vb:0x13b} to vbFlogChan
2020-09-09T12:03:06.857+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 381 got STREAMREQ status: ROLLBACK
2020-09-09T12:03:06.857+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 381 STREAMREQ metadataUpdated: true
2020-09-09T12:03:06.857+00:00 [Trace] [gocb] Writing request. 127.0.0.1:37580 to 127.0.0.1:11210 OP=0xd1. Opaque=331588
2020-09-09T12:03:06.858+00:00 [Info] Consumer::getKvNodesFromVbMap [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] Bucket: sync_gateway_sw1 kvNodes: [127.0.0.1:11210]
2020-09-09T12:03:06.861+00:00 [Trace] [gocb] Resolving response OP=0xd1. Opaque=331588
2020-09-09T12:03:06.861+00:00 [Trace] [gocb] Dispatching response callback. OP=0xd1. Opaque=331588
2020-09-09T12:03:06.861+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 381 STREAMREQ Failed. Inserting entry: &consumer.vbFlogEntry{flog:(*memcached.FailoverLog)(nil), seqNo:0x0, signalStreamEnd:false, statusCode:0x23, streamReqRetry:true, vb:0x17d} to vbFlogChan
2020-09-09T12:03:06.861+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 389 got STREAMREQ status: ROLLBACK
2020-09-09T12:03:06.861+00:00 [Info] Consumer::processDCPEvents [worker_task_update_1:/tmp/127.0.0.1:8091_1_4223910612.sock:15242] vb: 389 STREAMREQ metadataUpdated: true
2020-09-09T12:03:06.861+00:00 [Trace] [gocb] Writing request. 127.0.0.1:37580 to 127.0.0.1:11210 OP=0xd1. Opaque=331589
@dipen_patel, I am sure it is something trivial, it would be best to supply your actual JavaScript code (and perhaps a picture of your Settings).
I would hazard to guess that you have an incorrect bucket binding/alias and your writes from your Handler code are blocking/retrying for 60 seconds until they give up - thus the backlog is most likely moving forward but very slowly.
I am concerned about your “Failed. Inserting entry” perhaps you have a bad bucket alias, please walk through some examples from main document (refer to eventing-examples.html)
Note in the system (common log) you should be seeing much cleaner output.
The only other piece of advice I can give is to use a try/catch block and then use the log(…) statement for example:
// To run need a Binding in this Function's Settings as follows:
// 1. Bucket Alias
// 2. dst_bkt
// 3. destination
// 4. read+write
function OnUpdate(doc, meta) {
try {
// filter out non-interesting docs
if (doc.type !== "basic_bkt_ops") return;
// Assuming 'dst_bkt' is a bucket alias binding in this case to a non source bucket
log("OnUpdate got mutation for id", meta.id, "doc", doc);
// make a key based on the meta.id of the input mutation
var dst_key = "dst_" + meta.id;
// make a document to write, include the input mutation's doc
var doc_to_wr = {
"status": 3,
"mutation": doc
};
// this is a bucket SET operation.
dst_bkt[dst_key] = doc_to_wr;
log("wrote DOC to dst_bkt with id", dst_key, doc_to_wr);
// this is a bucket GET operation.
var doc_read = dst_bkt[dst_key];
log("read DOC from dst_bkt with id", dst_key, doc_read);
// this is a bucket DEL operation.
delete dst_bkt[dst_key];
log("deleted " + dst_key + " from dst_bkt");
} catch (e) {
log("ISSUE something went wrong", e);
}
}