Details
-
Bug
-
Resolution: Done
-
Critical
-
5.0.0
-
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) |