Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-48603

[System Test] XDCR logs are filled with "execution timed out" error messages

    XMLWordPrintable

Details

    Description

      Test -

      -test tests/integration/neo/test_neo_kv_gsi_coll_xdcr_backup_sgw_fts_itemct_txns_eventing_cbas_scale3_magma.yml -scope tests/integration/neo/scope_neo_with_backup_magma.yml
      

      Day - 1
      Cycle - 1
      Scale - 3

      On 172.23.108.103
      goxdcr.log

      2021-09-26T14:03:06.450-07:00 ERRO GOXDCR.P2PManager: P2PSend resulted in Post "http://172.23.98.135:8091/xdcr/p2pCommunications": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
      2021-09-26T14:03:06.451-07:00 WARN GOXDCR.Utils: ExponentialBackoffExecutor for sendPeerToPeerReq(VBMasterCheck) encountered error (172.23.98.135:8091 : Post "http://172.23.98.135:8091/xdcr/p2pCommunications": context deadline exceeded (Client.Timeout exceeded while awaiting headers)). Sleeping 25.6s
      2021-09-26T14:03:07.166-07:00 INFO GOXDCR.ResourceMgr: Resource Manager State = overallTP: 0 highTP: 0 highExist: true lowExist: false backlogExist: true maxTP: 0 highTPNeeded: 1063479060 highTokens: 0 maxTokens: 0 lowTPLimit: 0 calibration: None dcpAction: Reset processCpu: 9 idleCpu: 72
      2021-09-26T14:03:07.166-07:00 INFO GOXDCR.ResourceMgr: backlogCount=999, noBacklogCount=0 extraQuota=false cpuNotMaxedCount=0 throughputDropCount=0
      2021-09-26T14:03:07.166-07:00 INFO GOXDCR.ResourceMgr: DcpPriorityMap=map[]
      ongoingReplMap=map[0d53a5e6437fbb31d3ffddd9e55c21c6/bucket4/bucket4:true 0d53a5e6437fbb31d3ffddd9e55c21c6/bucket8/bucket8:true 0d53a5e6437fbb31d3ffddd9e55c21c6/bucket9/bucket9:true 0d53a5e6437fbb31d3ffddd9e55c21c6/default/remote:true backfill_0d53a5e6437fbb31d3ffddd9e55c21c6/bucket4/bucket4:true backfill_0d53a5e6437fbb31d3ffddd9e55c21c6/bucket8/bucket8:true backfill_0d53a5e6437fbb31d3ffddd9e55c21c6/bucket9/bucket9:true]
      2021-09-26T14:03:08.158-07:00 ERRO GOXDCR.P2PManager: P2PSend resulted in Post "http://172.23.98.135:8091/xdcr/p2pCommunications": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
      2021-09-26T14:03:08.158-07:00 WARN GOXDCR.Utils: ExponentialBackoffExecutor for sendPeerToPeerReq(VBMasterCheck) encountered error (172.23.98.135:8091 : Post "http://172.23.98.135:8091/xdcr/p2pCommunications": context deadline exceeded (Client.Timeout exceeded while awaiting headers)). Sleeping 6.4s
      2021-09-26T14:03:08.352-07:00 ERRO GOXDCR.P2PManager: P2PSend resulted in Post "http://172.23.98.135:8091/xdcr/p2pCommunications": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
      2021-09-26T14:03:08.352-07:00 WARN GOXDCR.Utils: ExponentialBackoffExecutor for sendPeerToPeerReq(VBMasterCheck) encountered error (172.23.98.135:8091 : Post "http://172.23.98.135:8091/xdcr/p2pCommunications": context deadline exceeded (Client.Timeout exceeded while awaiting headers)). Sleeping 25.6s
      2021-09-26T14:03:10.687-07:00 INFO GOXDCR.StatsMgr: Stats for pipeline 0d53a5e6437fbb31d3ffddd9e55c21c6/bucket9/bucket9-474139785 {"Backfill Old Progress": "Source nozzles have been closed", "Backfill Progress": "Pipeline has been stopped", "Errors": "[{\"time\":\"2021-09-26T14:00:46.781240714-07:00\",\"errMsg\":\"TopoChangeDet : json: cannot unmarshal array into Go value of type map[string]interface {}\"}]", "OldProgress": "Pipeline is running", "Overview": {"CurrentTime": 1632690046779724769, "add_docs_written": 0, "bandwidth_usage": 0, "changes_left": 124156, "data_merged": 0, "data_replicated": 0, "datapool_failed_gets": 0, "dcp_datach_length": 0, "dcp_dispatch_time": 0, "deletion_docs_written": 0, "deletion_failed_cr_source": 0, "deletion_filtered": 0, "deletion_received_from_dcp": 0, "docs_checked": 0, "docs_cloned": 0, "docs_failed_cr_source": 0, "docs_filtered": 0, "docs_merged": 0, "docs_opt_repd": 0, "docs_processed": 0, "docs_received_from_dcp": 0, "docs_rep_queue": 0, "docs_unable_to_filter": 0, "docs_written": 0, "expiry_docs_merged": 0, "expiry_docs_written": 0, "expiry_failed_cr_source": 0, "expiry_filtered": 0, "expiry_received_from_dcp": 0, "expiry_stripped": 0, "num_checkpoints": 0, "num_failedckpts": 0, "rate_doc_checks": 0, "rate_doc_opt_repd": 0, "rate_received_from_dcp": 0, "rate_replicated": 0, "resp_wait_time": 0, "set_docs_written": 0, "set_failed_cr_source": 0, "set_filtered": 0, "set_received_from_dcp": 0, "size_rep_queue": 0, "target_docs_skipped": 0, "throttle_latency": 0, "throughput_throttle_latency": 0, "time_committing": 0, "wtavg_docs_latency": 0, "wtavg_get_doc_latency": 0, "wtavg_merge_latency": 0, "wtavg_meta_latency": 0}, "Progress": "Received error report : json: cannot unmarshal array into Go value of type map[string]interface {}", "Status": "Pending"}
       
      2021-09-26T14:03:10.687-07:00 INFO GOXDCR.XmemNozzle: xmem_0d53a5e6437fbb31d3ffddd9e55c21c6/bucket9/bucket9_172.23.105.168:11210_0 state =2 connType=MemConn received 0 items (0 compressed), sent 0 items (0 compressed), target items skipped 0, ignored 0 items, 0 items waiting to confirm, 0 in queue, 0 in current batch, avg wait time is 0ms, size of last ten batches processed [0,0,0,0,0,0,0,0,0,0], len(batches_ready_queue)=0, resend=0, locked=0, repair_count_getMeta=0, repair_count_setMeta=0, retry_cr=0, to resolve=0, to setback=0
      2021-09-26T14:03:10.687-07:00 INFO GOXDCR.XmemNozzle: xmem_0d53a5e6437fbb31d3ffddd9e55c21c6/bucket9/bucket9_172.23.105.168:11210_1 state =2 connType=MemConn received 0 items (0 compressed), sent 0 items (0 compressed), target items skipped 0, ignored 0 items, 0 items waiting to confirm, 0 in queue, 0 in current batch, avg wait time is 0ms, size of last ten batches processed [0,0,0,0,0,0,0,0,0,0], len(batches_ready_queue)=0, resend=0, locked=0, repair_count_getMeta=0, repair_count_setMeta=0, retry_cr=0, to resolve=0, to setback=0
      2021-09-26T14:03:10.687-07:00 INFO GOXDCR.DcpNozzle: dcp_0d53a5e6437fbb31d3ffddd9e55c21c6/bucket9/bucket9_172.23.96.148:11210_0 received 0 items (0 compressed), sent 0 items. streams inactive: map[258:0 259:0 260:0 261:0 262:0 263:0 264:0 265:0 266:0 267:0 268:0 269:0 270:0 271:0 272:0 273:0 274:0 275:0 276:0 277:0 278:0 279:0 280:0 281:0 282:0 283:0 284:0 285:0 286:0 287:0 288:0 289:0 290:0 291:0 292:0 293:0 294:0 295:0 296:0 297:0 298:0 299:0 300:0]
      2021-09-26T14:03:10.687-07:00 INFO GOXDCR.DcpNozzle: dcp_0d53a5e6437fbb31d3ffddd9e55c21c6/bucket9/bucket9_172.23.96.148:11210_1 received 0 items (0 compressed), sent 0 items. streams inactive: map[301:0 302:0 303:0 304:0 305:0 306:0 307:0 308:0 309:0 310:0 311:0 312:0 313:0 314:0 315:0 316:0 317:0 318:0 319:0 320:0 321:0 322:0 323:0 324:0 325:0 326:0 327:0 328:0 329:0 330:0 331:0 332:0 333:0 334:0 335:0 336:0 337:0 338:0 339:0 340:0 341:0 342:0 343:0]
      2021-09-26T14:03:10.687-07:00 INFO GOXDCR.ThrSeqTrackSvc: 0d53a5e6437fbb31d3ffddd9e55c21c6/bucket9/bucket9_ThroughSeqnoTracker time_spent=82.266µs num_vb=86 max_sent=0 avg_sent=0 max_filtered=0 avg_filtered=0 max_failed_cr=0 avg_failed_cr=0 max_gap=0 avg_gap=0 oso_received=0
      2021-09-26T14:03:10.969-07:00 ERRO GOXDCR.P2PManager: P2PSend resulted in Post "http://172.23.98.135:8091/xdcr/p2pCommunications": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
      2021-09-26T14:03:10.969-07:00 WARN GOXDCR.Utils: ExponentialBackoffExecutor for sendPeerToPeerReq(VBMasterCheck) encountered error (172.23.98.135:8091 : Post "http://172.23.98.135:8091/xdcr/p2pCommunications": context deadline exceeded (Client.Timeout exceeded while awaiting headers)). Sleeping 3.2s
      2021-09-26T14:03:11.374-07:00 ERRO GOXDCR.P2PManager: 0 Request to 172.23.98.135:8091 with opaque 3206152192 timed out
      2021-09-26T14:03:11.500-07:00 INFO GOXDCR.P2PManager: Received VB master check request from 172.23.105.107:8091 with specID 0d53a5e6437fbb31d3ffddd9e55c21c6/default/remote for the following Bucket -> VBs map[default:[514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559 560 561 562 563 564 565 566 567 568 569 570 571 572 573 574 575 576 577 578 579 580 581 582 583 584 585 586 587 588 589 590 591 592 593 594 595 596 597 598]]
      2021-09-26T14:03:11.503-07:00 INFO GOXDCR.CheckpointSvc: GetMappingsDoc 0d53a5e6437fbb31d3ffddd9e55c21c6/default/remote retrieved an existing mappingsDoc
      2021-09-26T14:03:11.504-07:00 INFO GOXDCR.CheckpointSvc: GetMappingsDoc backfill_0d53a5e6437fbb31d3ffddd9e55c21c6/default/remote retrieved an existing mappingsDoc
      2021-09-26T14:03:11.505-07:00 INFO GOXDCR.CheckpointSvc: GetMappingsDoc backfill_0d53a5e6437fbb31d3ffddd9e55c21c6/default/remote retrieved an existing mappingsDoc
      2021-09-26T14:03:11.505-07:00 INFO GOXDCR.CheckpointSvc: Loaded brokenMap: map[]
      2021-09-26T14:03:11.505-07:00 INFO GOXDCR.P2PManager: Handler for backfill_0d53a5e6437fbb31d3ffddd9e55c21c6/default/remote retrieving CheckpointsDocs request found 0 docs
      2021-09-26T14:03:12.191-07:00 ERRO GOXDCR.P2PManager: P2PSend resulted in Post "http://172.23.98.135:8091/xdcr/p2pCommunications": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
      2021-09-26T14:03:12.191-07:00 WARN GOXDCR.Utils: ExponentialBackoffExecutor for sendPeerToPeerReq(VBMasterCheck) encountered error (172.23.98.135:8091 : Post "http://172.23.98.135:8091/xdcr/p2pCommunications": context deadline exceeded (Client.Timeout exceeded while awaiting headers)). Sleeping 400ms
      

      2021-09-26T14:03:41.988-07:00 INFO GOXDCR.GenericPipeline: Executing Action timed out
      2021-09-26T14:03:41.989-07:00 INFO GOXDCR.GenericPipeline: ****************************
      2021-09-26T14:03:41.989-07:00 ERRO GOXDCR.GenericPipeline: 0d53a5e6437fbb31d3ffddd9e55c21c6/bucket4/bucket4-980076789 failed to start, err=map[genericPipeline.RunP2PProtocol:Execution timed out]
      2021-09-26T14:03:41.989-07:00 ERRO GOXDCR.PipelineMgr: Failed to start the pipeline 0d53a5e6437fbb31d3ffddd9e55c21c6/bucket4/bucket4-980076789
      2021-09-26T14:03:41.989-07:00 ERRO GOXDCR.PipelineMgr: Failed to update pipeline 0d53a5e6437fbb31d3ffddd9e55c21c6/bucket4/bucket4, err=genericPipeline.RunP2PProtocol : Execution timed out
      2021-09-26T14:03:41.989-07:00 ERRO GOXDCR.PipelineMgr: Update of pipeline 0d53a5e6437fbb31d3ffddd9e55c21c6/bucket4/bucket4 failed with errors=genericPipeline.RunP2PProtocol : Execution timed out
      2021-09-26T14:03:41.989-07:00 INFO GOXDCR.PipelineMgr: Replication 0d53a5e6437fbb31d3ffddd9e55c21c6/bucket4/bucket4 update experienced error(s): genericPipeline.RunP2PProtocol : Execution timed out. Scheduling a redo.
      2021-09-26T14:03:41.989-07:00 INFO GOXDCR.PipelineMgr: Replication status is updated with error(s) genericPipeline.RunP2PProtocol : Execution timed out, current status=name={0d53a5e6437fbb31d3ffddd9e55c21c6/bucket4/bucket4}, status={Pending}, errors={[{"time":"2021-09-26T14:03:41.989211803-07:00","errMsg":"genericPipeline.RunP2PProtocol:Execution timed out"},{"time":"2021-09-26T14:02:31.953895219-07:00","errMsg":"genericPipeline.RunP2PProtocol:Execution timed out"},{"time":"2021-09-26T14:01:21.919006611-07:00","errMsg":"genericPipeline.RunP2PProtocol:Execution timed out"},{"time":"2021-09-26T14:00:11.882799509-07:00","errMsg":"RuntimeCtx:Execution timed out"},{"time":"2021-09-26T13:57:06.778132645-07:00","errMsg":"TopoChangeDet : json: cannot unmarshal array into Go value of type map[string]interface {}"},{"time":"2021-09-26T13:57:06.778046935-07:00","errMsg":"TopoChangeDet : json: cannot unmarshal array into Go value of type map[string]interface {}"}]}, oldProgress={Performing PeerToPeer communication and metadata merging}, progress={Pipeline failed to start, err=map[genericPipeline.RunP2PProtocol:Execution timed out]}, oldBackfillProgress={Source nozzles have been closed}, backfillProgress={Pipeline has been stopped}
      

      REST calls are also failing with Unexpected server error, request logged.

      2021-09-26T13:34:44.769-07:00 ERRO GOXDCR.CapiSvc: Failed to unmarshal the response as json, err=json: cannot unmarshal array into Go value of type map[string]interface {}, bod=["Unexpected server error, request logged."]
       res=&{500 Internal Server Error 500 HTTP/1.1 1 1 map[Cache-Control:[no-cache,no-store,must-revalidate] Content-Length:[44] Content-Type:[application/json] Date:[Sun, 26 Sep 2021 20:34:05 GMT] Expires:[Thu, 01 Jan 1970 00:00:00 GMT] Pragma:[no-cache] Server:[Couchbase Server] X-Content-Type-Options:[nosniff] X-Frame-Options:[DENY] X-Permitted-Cross-Domain-Policies:[none] X-Xss-Protection:[1; mode=block]] 0xc12ae17d20 44 [] false false map[] 0xc10efc8100 <nil>}
      

      Attachments

        Issue Links

          No reviews matched the request. Check your Options in the drop-down menu of this sections header.

          Activity

            People

              sujay.gad Sujay Gad
              sujay.gad Sujay Gad
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Gerrit Reviews

                  There are no open Gerrit changes

                  PagerDuty