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

sync gateway panic&restart with nil doc.body

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Critical
    • 5.5.0
    • 5.0.0
    • convergence
    • Untriaged
    • No

    Description

      Our system-test has a single gateway running build 1.5.0-538 with the following config to enable xattrs: 

      https://gist.github.com/tahmmee/505e998d923dd83555b8e4bcd9beb8e0

      As part of our longevity testing, we run the mobile testkit's dotnet container  against the gateway which in turn loads docs into the default bucket.

      [2017-08-10T14:43:36-07:00, sequoiatools/testkit-net:56eb9a] dotnet run --replication-endpoint blip://172.23.99.23:4984/db --runtime-min 120 --max-docs 10000

       * Note there are other data loaders in the background pushing data into the same default bucket.  further information regarding other operations in the cluster described here: https://github.com/couchbaselabs/sequoia/blob/master/tests/integration/README.md

       

      So this morning I noticed we had 3 instances of sync gateway running on the host.  I stopped them all and then started just 1.  Problem is that the gateway panics and restart on every start with following error:

      2017-08-28T09:48:05.545-07:00 Enabling logging: [* Import+]
      2017-08-28T09:48:05.545-07:00 ==== Couchbase Sync Gateway/1.5.0(538;591002d) ====
      2017-08-28T09:48:05.545-07:00 requestedSoftFDLimit >= currentHardFdLimit (5000 >= 4096) capping at 4096
      2017-08-28T09:48:05.545-07:00 Configured process to allow 4096 open file descriptors
      2017-08-28T09:48:05.545-07:00 Opening db /db as bucket "default", pool "default", server <http://172.23.108.103:8091>
      2017-08-28T09:48:05.545-07:00 GoCBCustomSGTranscoder Opening Couchbase database default on <http://172.23.108.103:8091> as user "Administrator"
      2017-08-28T09:48:09.569-07:00 Cache: Initializing changes cache with options {ChannelCacheOptions:{ChannelCacheMinLength:0 ChannelCacheMaxLength:0 ChannelCacheAge:0s} CachePendingSeqMaxWait:5s CachePendingSeqMaxNum:10000 CacheSkippedSeqMaxWait:1h0m0s}
      2017-08-28T09:48:09.569-07:00 Feed: Starting mutation feed on bucket default due to either channel cache mode or doc tracking (auto-import/bucketshadow)
      2017-08-28T09:48:09.569-07:00 Feed: Using DCP feed for bucket: "default" (based on feed_type specified in config file)
      2017-08-28T09:48:09.636-07:00 Feed+: Seeding seqnos: map[513:881732 98:907680 245:883612 443:862116 538:884118 807:342387 174:884367 228:380168 418:382822 332:48629 233:854186 412:382233 557:111383 258:299581 259:677547 537:403634 625:771401 437:380694 622:342701 87:886269 520:887384 982:111911 94:412237 518:885739 612:849975 679:111759 302:343263 555:111164 805:774211 641:343273 676:48728 570:412113 815:771562 569:882058 972:49394 226:381433 969:48269 980:48469 808:349318 307:770156 546:881224 237:381340 223:882486 261:298917 577:882394 599:380691 263:674638 575:397765 958:48701 176:399916 620:773222 572:403123 671:111860 578:402224 669:48136 181:895194 291:771115 673:49789 295:772713 811:771767 573:399830 634:342886 674:48353 816:779043 530:1368665 975:48085 90:881499 540:954167 624:773175 787:770897 794:771241 253:1368340 818:407587 240:899320 515:399785 568:1365643 604:850442 978:48106 678:112103 804:768621 535:400268 552:60890 960:48402 331:48615 533:880764 663:111906 306:768714 411:850902 598:386005 225:855123 301:1196961 516:881200 273:299070 589:380378 548:110998 564:881142 610:853460 813:771461 563:48569 171:399716 340:111557 292:770434 602:878563 647:771974 588:381245 819:352426 427:424854 635:770879 659:48230 576:1367652 642:769065 656:49593 75:480883 236:381286 524:400452 77:882806 626:343376 664:111157 267:300258 431:848227 526:399676 180:1051326 419:413678 965:111882 83:1364934 658:110220 413:382612 523:399414 543:885151 590:853350 172:410058 422:851154 601:382956 621:787997 271:678259 623:770235 802:797308 264:1053872 542:399489 565:882451 786:770937 178:410005 231:379868 683:48948 583:847674 93:892079 187:881609 817:1198185 561:49346 95:431167 571:945336 681:111292 632:1201670 305:768830 986:50904 84:903527 579:401003 660:48626 255:400737 517:400276 85:879828 248:399798 637:343261 796:767789 973:174358 425:1322471 554:173081 88:402622 175:883790 247:399837 605:1322255 272:299729 607:380730 661:48597 806:343334 246:435066 638:771937 337:48479 244:428480 442:852571 547:111069 433:852480 680:112138 266:299032 962:111447 426:856000 977:111170 416:850720 665:174162 257:848857 613:1321006 989:110264 434:854507 611:849076 616:343207 655:48527 304:1196847 329:111092 81:400959 423:851574 668:111027 234:381114 531:880074 976:173313 73:877589 636:343919 646:342543 100:881645 421:381090 639:771937 238:852261 791:344316 974:48801 560:111664 628:344305 550:49022 297:769854 544:936964 299:774002 549:173548 594:1321987 627:344631 326:110721 188:399025 558:116306 790:342643 675:110692 559:48312 963:111799 80:399704 441:381457 595:859156 957:112022 967:48599 242:1364235 528:401206 256:933724 603:859448 682:48384 262:674675 325:48227 410:486184 232:849738 532:881293 801:342813 984:112331 72:399729 79:881939 438:382843 186:883291 97:399356 179:879343 566:884180 581:434733 417:852518 633:342430 793:343443 268:298698 71:881409 615:381129 652:111637 182:471715 587:381951 985:111047 593:914919 797:770844 666:49012 814:772265 536:400058 440:381199 788:770939 183:402461 606:854096 243:879737 99:931162 798:343365 970:111446 300:771274 439:383034 527:1365517 574:883376 592:862909 96:400512 249:504954 333:48225 619:767876 961:48536 338:111383 415:849500 618:772777 648:770864 89:889166 435:850251 987:48719 250:398252 631:772453 649:770033 981:48933 251:915706 534:400043 260:299422 86:423022 667:48332 585:852620 630:816383 230:851128 800:772038 809:343384 514:401655 539:910272 298:767945 229:854362 334:110941 430:861828 959:48625 269:675334 432:381212 803:1201880 519:934888 78:1362479 591:1323729 596:850080 643:342123 227:382499 654:48386 956:111578 567:1364483 609:856124 185:403159 812:1197936 444:852677 74:399967 294:341846 640:342495 252:879389 341:173573 541:398642 789:816235 414:1322498 521:887576 651:173086 303:355119 562:48486 584:487254 76:883283 597:854354 529:884907 177:400709 964:112188 92:1367891 429:395394 600:404767 241:880498 69:398302 556:49586 336:48305 677:49105 988:48251 173:399505 810:771280 799:780888 270:679048 293:342655 328:172970 551:48180 608:381695 91:400923 70:398644 586:381341 645:780972 82:880278 795:1197037 327:173741 420:851372 582:381480 617:396530 644:1196986 629:342785 335:49626 968:111465 522:912033 672:111672 424:381399 983:111512 235:899234 296:343104 653:49487 339:111687 34:675188 614:381147 525:399582 662:173019 971:112182 184:400149 436:1325231 979:110760 545:401660 966:110653 224:1324386 553:48448 254:883983 428:381930 650:111051 657:116937 101:879556 792:343476 265:299324 102:879234 670:110647 330:48595]
      2017-08-28T09:48:09.637-07:00 Feed+: Connecting to new bucket datasource.  URLs:[http://172.23.108.103:8091 http://172.23.108.104:8091 http://172.23.99.20:8091 http://172.23.99.21:8091 http://172.23.99.22:8091 http://172.23.106.188:8091 http://172.23.107.47:8091 http://172.23.108.107:8091 http://172.23.97.237:8091 http://172.23.97.238:8091 http://172.23.97.239:8091 http://172.23.97.242:8091 http://172.23.99.25:8091], pool:default, bucket:default
      2017-08-28T09:48:09.638-07:00 Shadow: Watching doc changes...
      2017-08-28T09:48:09.642-07:00 Importing documents...
      _time=2017-08-28T09:48:10.297-07:00 _level=INFO _msg=Using plain authentication for user Administrator 
      _time=2017-08-28T09:48:10.298-07:00 _level=INFO _msg=Using plain authentication for user Administrator 
      _time=2017-08-28T09:48:10.298-07:00 _level=INFO _msg=Using plain authentication for user Administrator 
      _time=2017-08-28T09:48:10.305-07:00 _level=INFO _msg=Using plain authentication for user Administrator 
      _time=2017-08-28T09:48:10.308-07:00 _level=INFO _msg=Using plain authentication for user Administrator 
      2017-08-28T09:48:10.324-07:00 Feed: Got shadow event:00000000000000000404
      2017-08-28T09:48:10.324-07:00 CRUD+: No xattr content found for key=8EF6F9FD-91_187676, xattrKey=_sync: sub-document path does not exist
      2017-08-28T09:48:10.325-07:00 WARNING: changeCache: Doc "8EF6F9FD-91_187676" does not have valid sync data. -- db.(*changeCache).DocChangedSynchronous() at change_cache.go:409
      2017-08-28T09:48:10.325-07:00 Feed: Got shadow event:8EF6F9FD-91_187676
      2017-08-28T09:48:10.325-07:00 CRUD+: No xattr content found for key=9CB6CCC4-22_187115, xattrKey=_sync: sub-document path does not exist
      2017-08-28T09:48:10.325-07:00 WARNING: changeCache: Doc "9CB6CCC4-22_187115" does not have valid sync data. -- db.(*changeCache).DocChangedSynchronous() at change_cache.go:409
      2017-08-28T09:48:10.325-07:00 CRUD: Importing new doc "8EF6F9FD-91_187676"
      2017-08-28T09:48:10.325-07:00 Feed: Got shadow event:00000000000000000128
      2017-08-28T09:48:10.326-07:00 Feed: Got shadow event:00000000000000001226
      2017-08-28T09:48:10.326-07:00 Feed: Got shadow event:9CB6CCC4-22_187115
      2017-08-28T09:48:10.326-07:00 Feed: Got shadow event:00000000000000000628
      2017-08-28T09:48:10.326-07:00 Feed: Got shadow event:00000000000000001504
      2017-08-28T09:48:10.326-07:00 Feed: Got shadow event:00000000000000001127
      2017-08-28T09:48:10.326-07:00 CRUD: Importing new doc "9CB6CCC4-22_187115"
      2017-08-28T09:48:10.327-07:00 CRUD+: No xattr content found for key=8EF6F9FD-91_187665, xattrKey=_sync: sub-document path does not exist
      2017-08-28T09:48:10.327-07:00 WARNING: changeCache: Doc "8EF6F9FD-91_187665" does not have valid sync data. -- db.(*changeCache).DocChangedSynchronous() at change_cache.go:409
      2017-08-28T09:48:10.328-07:00 Feed: Got shadow event:8EF6F9FD-91_187665
      2017-08-28T09:48:10.328-07:00 CRUD: Importing new doc "8EF6F9FD-91_187665"
      2017-08-28T09:48:10.332-07:00 Import+: Ignoring delete mutation for EF1DC3F4-73_285974 - no existing Sync Gateway metadata.
      2017-08-28T09:48:10.332-07:00 Feed: Got shadow event:EF1DC3F4-73_285974
      2017-08-28T09:48:10.332-07:00 Feed: Got shadow event:00000000000000000711
      2017-08-28T09:48:10.332-07:00 CRUD: Importing new doc "EF1DC3F4-73_285974"
      2017-08-28T09:48:10.332-07:00 Cache+: Unable to unmarshal sync metadata for feed document "39F958060F14C1EA62505D859629E2369597508A97E50344E529ABF77D9ABB5FF6D2DFB4C15173BB".  Will not be included in channel cache.  Error: json: cannot unmarshal number into Go value of type db.documentRoot
      2017-08-28T09:48:10.332-07:00 Feed: Got shadow event:39F958060F14C1EA62505D859629E2369597508A97E50344E529ABF77D9ABB5FF6D2DFB4C15173BB
      2017-08-28T09:48:10.332-07:00 CRUD+: No xattr content found for key=8EF6F9FD-91_187691, xattrKey=_sync: sub-document path does not exist
      2017-08-28T09:48:10.332-07:00 WARNING: Error unmarshaling doc "39F958060F14C1EA62505D859629E2369597508A97E50344E529ABF77D9ABB5FF6D2DFB4C15173BB": json: cannot unmarshal number into Go value of type db.documentRoot -- db.(*document).UnmarshalJSON() at document.go:447
      2017-08-28T09:48:10.332-07:00 Feed: Got shadow event:00000000000000001324
      2017-08-28T09:48:10.333-07:00 CRUD+: No xattr content found for key=31C96B55-40_187671, xattrKey=_sync: sub-document path does not exist
      2017-08-28T09:48:10.333-07:00 Feed: Got shadow event:00000000000000000309
      2017-08-28T09:48:10.333-07:00 WARNING: changeCache: Doc "8EF6F9FD-91_187691" does not have valid sync data. -- db.(*changeCache).DocChangedSynchronous() at change_cache.go:409
      panic: assignment to entry in nil map
       
      goroutine 63 [running]:
      panic(0xb23320, 0xc4201c4510)
      /usr/local/go/1.7.4/go/src/runtime/panic.go:500 +0x1a1
      github.com/couchbase/sync_gateway/db.(*Database).initializeSyncData(0xc4204a59c0, 0xc42030c900, 0x0, 0xd)
      /home/couchbase/jenkins/workspace/sgw-unix-build/1.5.0/enterprise/godeps/src/github.com/couchbase/sync_gateway/db/crud.go:526 +0x115
      github.com/couchbase/sync_gateway/db.(*DatabaseContext).assimilate.func1(0xc42030c900, 0xc420283340, 0x8, 0x476d01, 0xc4201c4318)
      /home/couchbase/jenkins/workspace/sgw-unix-build/1.5.0/enterprise/godeps/src/github.com/couchbase/sync_gateway/db/assimilator.go:41 +0x7a
      github.com/couchbase/sync_gateway/db.(*Database).updateAndReturnDoc.func1(0xc42030c900, 0x100, 0x0, 0x0, 0x0, 0xc42030c900, 0x0)
      /home/couchbase/jenkins/workspace/sgw-unix-build/1.5.0/enterprise/godeps/src/github.com/couchbase/sync_gateway/db/crud.go:740 +0xff
      github.com/couchbase/sync_gateway/db.(*Database).updateAndReturnDoc.func2(0x0, 0x0, 0x0, 0xbeedf2, 0x7, 0xc4201c51a0, 0x7, 0x0, 0x0)
      /home/couchbase/jenkins/workspace/sgw-unix-build/1.5.0/enterprise/godeps/src/github.com/couchbase/sync_gateway/db/crud.go:961 +0x10c
      github.com/couchbase/sync_gateway/base.CouchbaseBucketGoCB.WriteUpdate(0xc42009aa20, 0xc4201c2bc0, 0x1a, 0xbeedf2, 0x7, 0xc4201c51a0, 0x7, 0x0, 0x0, 0xfc29c0, ...)
      /home/couchbase/jenkins/workspace/sgw-unix-build/1.5.0/enterprise/godeps/src/github.com/couchbase/sync_gateway/base/bucket_gocb.go:1352 +0x17e
      github.com/couchbase/sync_gateway/base.(*CouchbaseBucketGoCB).WriteUpdate(0xc4201a2dc0, 0xc4204a57a0, 0x12, 0x0, 0xc42044d480, 0xc4201325a0, 0x34)
      <autogenerated>:477 +0xc9
      github.com/couchbase/sync_gateway/db.(*Database).updateAndReturnDoc(0xc4204a59c0, 0xc4204a57a0, 0x12, 0x204a5901, 0x0, 0xc4204a59e0, 0xc4204a59f0, 0xc4204a59c0, 0xb5bc80, 0xc4204a5901, ...)
      /home/couchbase/jenkins/workspace/sgw-unix-build/1.5.0/enterprise/godeps/src/github.com/couchbase/sync_gateway/db/crud.go:971 +0x20c9
      github.com/couchbase/sync_gateway/db.(*Database).updateDoc(0xc4204a59c0, 0xc4204a57a0, 0x12, 0x1, 0xc4204a59e0, 0x1, 0x1, 0x0, 0x4535c0)
      /home/couchbase/jenkins/workspace/sgw-unix-build/1.5.0/enterprise/godeps/src/github.com/couchbase/sync_gateway/db/crud.go:702 +0x70
      github.com/couchbase/sync_gateway/db.(*DatabaseContext).assimilate(0xc420368280, 0xc4204a57a0, 0x12)
      /home/couchbase/jenkins/workspace/sgw-unix-build/1.5.0/enterprise/godeps/src/github.com/couchbase/sync_gateway/db/assimilator.go:45 +0x1ba
      created by github.com/couchbase/sync_gateway/db.(*DatabaseContext).watchDocChanges
      /home/couchbase/jenkins/workspace/sgw-unix-build/1.5.0/enterprise/godeps/src/github.com/couchbase/sync_gateway/db/assimilator.go:26 +0x325
      tail: /data/sync_gateway.log: file truncated
      2017-08-28T09:48:11.942-07:00 Enabling logging: [* Import+]
      2017-08-28T09:48:11.942-07:00 ==== Couchbase Sync Gateway/1.5.0(538;591002d) ====
      2017-08-28T09:48:11.942-07:00 requestedSoftFDLimit >= currentHardFdLimit (5000 >= 4096) capping at 4096
      2017-08-28T09:48:11.942-07:00 Configured process to allow 4096 open file descriptors
      2017-08-28T09:48:11.942-07:00 Opening db /db as bucket "default", pool "default", server <http://172.23.108.103:8091>
      2017-08-28T09:48:11.942-07:00 GoCBCustomSGTranscoder Opening Couchbase database default on <http://172.23.108.103:8091> as user "Administrator"

       

      where /db/crud.go:526 is

      func (db *Database) initializeSyncData(doc *document) (err error) {
        body := doc.body
        doc.CurrentRev = createRevID(1, "", body)
        body["_rev"] = doc.CurrentRev
        doc.setFlag(channels.Deleted, false)

      Attachments

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

        Activity

          People

            adamf Adam Fraser
            tommie Tommie McAfee (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Gerrit Reviews

                There are no open Gerrit changes

                PagerDuty