Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-10895

Duplicate indexes being created at the same time

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Duplicate
    • Affects Version/s: 2.4.2
    • Fix Version/s: None
    • Component/s: Indexing
    • Labels:
    • Operating System:
      ALL

      Description

      We have classes which handle the assignment of indexes to collections when our services start. This morning we pushed a service to production and the result was a totally corrupted collection.

      The service is deployed on two servers, starting in parallel they both call the code to build indexes in the background. There are issues which we are happy to carry on our shoulders however I believe there is something to investigate here where indexes with the same names and values are being created at the same time. Shouldn't Mongo be checking whether this is happening and prevent it from happening? See log lines below.

      Thanks,
      Matt

      Wed Sep 25 06:39:36.638 [initandlisten] connection accepted from 192.168.3.36:61075 #4284123 (113 connections now open)
      Wed Sep 25 06:39:36.717 [conn4284123] authenticate db: Normalisation

      { authenticate: 1, user: "daluser", nonce: "def6a2993a155352", key: "14285f67d7f0d8010ca0d27f50db4765" }

      Wed Sep 25 06:39:36.822 [conn4284123] build index Normalisation.Fixture

      { Date: -1 }

      background
      Wed Sep 25 06:39:36.931 [initandlisten] connection accepted from 192.168.3.37:55984 #4284124 (114 connections now open)
      Wed Sep 25 06:39:36.976 [conn4284124] authenticate db: Normalisation

      { authenticate: 1, user: "daluser", nonce: "88a6653c28201999", key: "60595ec90245f7606ad2ed8f389bc967" }

      Wed Sep 25 06:39:37.023 [conn4284124] build index Normalisation.Fixture

      { Date: -1 }

      background
      Wed Sep 25 06:39:38.361 [initandlisten] connection accepted from 192.168.3.36:61078 #4284125 (115 connections now open)
      Wed Sep 25 06:39:38.499 [conn4284125] end connection 192.168.3.36:61078 (114 connections now open)
      Wed Sep 25 06:39:38.609 [conn4284055] query DAL.Market query:

      { _id: "TipexSports|Interwetten|2370483|MatchResult" }

      ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:39654 reslen:2770 123ms
      Wed Sep 25 06:39:39.010 [conn4284123] Background Index Build Progress: 24200/66064 36%
      Wed Sep 25 06:39:39.368 [initandlisten] connection accepted from 192.168.3.36:61082 #4284126 (115 connections now open)
      Wed Sep 25 06:39:39.469 [initandlisten] connection accepted from 192.168.3.34:64384 #4284127 (116 connections now open)
      Wed Sep 25 06:39:39.472 [conn4284127] end connection 192.168.3.34:64384 (115 connections now open)
      Wed Sep 25 06:39:39.472 [conn4284126] end connection 192.168.3.36:61082 (115 connections now open)
      Wed Sep 25 06:39:40.004 [conn4284124] Background Index Build Progress: 24000/66064 36%
      Wed Sep 25 06:39:40.438 [initandlisten] connection accepted from 192.168.3.49:63643 #4284128 (115 connections now open)
      Wed Sep 25 06:39:40.493 [conn4284128] end connection 192.168.3.49:63643 (114 connections now open)
      Wed Sep 25 06:39:42.009 [conn4284123] Background Index Build Progress: 49600/66064 75%
      Wed Sep 25 06:39:42.758 [conn4284089] query DAL.Market query:

      { _id: "TipexSports|bwin|2434073|MatchResult" }

      ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:230 reslen:20 106ms
      Wed Sep 25 06:39:43.018 [conn4284124] Background Index Build Progress: 47800/66064 72%
      Wed Sep 25 06:39:43.820 [conn4284123] build index done. scanned 66064 total records. 6.997 secs
      Wed Sep 25 06:39:43.821 [conn4284123] insert Normalisation.system.indexes ninserted:1 keyUpdates:0 numYields: 472 locks(micros) w:5627156 7048ms
      Wed Sep 25 06:39:43.835 [conn4284123] build index Normalisation.Fixture

      { GroupId: -1 }

      background
      Wed Sep 25 06:39:44.936 [conn4284124] build index done. scanned 66064 total records. 7.912 secs
      Wed Sep 25 06:39:44.936 [conn4284124] insert Normalisation.system.indexes ninserted:1 keyUpdates:0 numYields: 549 locks(micros) w:8295646 7912ms
      Wed Sep 25 06:39:44.953 [conn4284124] build index Normalisation.Fixture

      { GroupId: -1 }

      background
      Wed Sep 25 06:39:46.005 [conn4284123] Background Index Build Progress: 19800/66064 29%
      Wed Sep 25 06:39:47.007 [conn4284124] Background Index Build Progress: 16300/66064 24%
      Wed Sep 25 06:39:47.185 [initandlisten] connection accepted from 192.168.3.36:61087 #4284129 (115 connections now open)
      Wed Sep 25 06:39:47.301 [conn4284129] end connection 192.168.3.36:61087 (114 connections now open)
      Wed Sep 25 06:39:47.453 [initandlisten] connection accepted from 192.168.3.37:55988 #4284130 (115 connections now open)
      Wed Sep 25 06:39:47.519 [conn4284130] end connection 192.168.3.37:55988 (114 connections now open)
      Wed Sep 25 06:39:48.362 [initandlisten] connection accepted from 192.168.3.36:61089 #4284131 (115 connections now open)
      Wed Sep 25 06:39:48.423 [conn4284131] end connection 192.168.3.36:61089 (114 connections now open)
      Wed Sep 25 06:39:49.015 [conn4284123] Background Index Build Progress: 40900/66064 61%
      Wed Sep 25 06:39:49.375 [initandlisten] connection accepted from 192.168.3.36:61093 #4284132 (115 connections now open)
      Wed Sep 25 06:39:49.513 [initandlisten] connection accepted from 192.168.3.34:64392 #4284133 (116 connections now open)
      Wed Sep 25 06:39:49.517 [conn4284133] end connection 192.168.3.34:64392 (115 connections now open)
      Wed Sep 25 06:39:49.518 [conn4284132] end connection 192.168.3.36:61093 (114 connections now open)
      Wed Sep 25 06:39:49.555 [conn4284040] update DAL.Market query:

      { _id: "TipexSports|188bet|2504061|Handicap|3.5" }

      update: { _id: "TipexSports|188bet|2504061|Handicap|3.5", KeyValues: [ "Tipe$
      Wed Sep 25 06:39:49.555 [conn4284089] update DAL.Market query:

      { _id: "TipexSports|Betsson Sportsbook|2345751|MatchResult" }

      update: { _id: "TipexSports|Betsson Sportsbook|2345751|MatchResul$
      Wed Sep 25 06:39:49.555 [conn4284093] update DAL.Market query:

      { _id: "TipexSports|Tipico|2336075|Handicap|0.5" }

      update: { _id: "TipexSports|Tipico|2336075|Handicap|0.5", KeyValues: [ "Tipe$
      Wed Sep 25 06:39:50.014 [conn4284124] Background Index Build Progress: 35400/66064 53%
      Wed Sep 25 06:39:50.448 [initandlisten] connection accepted from 192.168.3.49:63647 #4284134 (115 connections now open)
      Wed Sep 25 06:39:50.502 [conn4284134] end connection 192.168.3.49:63647 (114 connections now open)
      Wed Sep 25 06:39:50.514 [conn4284018] end connection 192.168.3.45:51289 (113 connections now open)
      Wed Sep 25 06:39:50.514 [initandlisten] connection accepted from 192.168.3.45:51291 #4284135 (114 connections now open)
      Wed Sep 25 06:39:50.570 [conn4284135] authenticate db: local

      { authenticate: 1, nonce: "79eed339cddddc82", user: "__system", key: "5210e5e40e47310b8c5f099c8d8d73f4" }

      Wed Sep 25 06:39:51.437 [conn4284019] end connection 192.168.3.42:52050 (113 connections now open)
      Wed Sep 25 06:39:51.574 [initandlisten] connection accepted from 192.168.3.42:52052 #4284136 (114 connections now open)
      Wed Sep 25 06:39:51.655 [conn4284136] authenticate db: local

      { authenticate: 1, nonce: "f504b1237e97239c", user: "__system", key: "f9a1a8af5aa7f311dac7384a0b804fa3" }

      Wed Sep 25 06:39:52.044 [conn4284123] Background Index Build Progress: 60100/66064 90%
      Wed Sep 25 06:39:52.929 [conn4284123] build index done. scanned 66064 total records. 9.093 secs
      Wed Sep 25 06:39:52.929 [conn4284123] insert Normalisation.system.indexes ninserted:1 keyUpdates:0 numYields: 578 locks(micros) w:8150359 9094ms
      Wed Sep 25 06:39:53.037 [conn4284124] Background Index Build Progress: 56000/66064 84%
      Wed Sep 25 06:39:53.166 [conn4284123] authenticate db: CMS_Cloud

      { authenticate: 1, user: "daluser", nonce: "a72732bcb92ac937", key: "1ebb0cb7a903a1210047d30c429d9572" }

      Wed Sep 25 06:39:53.286 [conn4284124] build index done. scanned 66064 total records. 8.333 secs
      Wed Sep 25 06:39:53.286 [conn4284124] insert Normalisation.system.indexes ninserted:1 keyUpdates:0 numYields: 562 locks(micros) w:8823126 8333ms
      Wed Sep 25 06:39:53.585 [conn4284124] authenticate db: CMS_Cloud

      { authenticate: 1, user: "daluser", nonce: "c1f6f981abe87170", key: "8e7c6549526f9dec8df1d0fd67d9f48c" }

      Wed Sep 25 06:39:53.598 [conn4284123] authenticate db: DAL

      { authenticate: 1, user: "daluser", nonce: "ed12e8b73cc28e89", key: "c2bed592eb609abde1fb24ccd97032e1" }

      Wed Sep 25 06:39:53.923 [conn4284124] authenticate db: DAL

      { authenticate: 1, user: "daluser", nonce: "a4b47f9104f299fc", key: "f28f8b7c7ddecf504c2341842467e10d" }

      Wed Sep 25 06:39:56.442 [conn4284123] query DAL.Fixture query: { Date:

      { $gte: new Date(1380067200000), $lte: new Date(253402300799999) }

      } cursorid:209177094897634530 ntoreturn:0 ntoskip:0 $
      Wed Sep 25 06:39:58.388 [initandlisten] connection accepted from 192.168.3.36:61105 #4284137 (115 connections now open)
      Wed Sep 25 06:39:58.564 [conn4284137] end connection 192.168.3.36:61105 (114 connections now open)
      Wed Sep 25 06:39:59.118 [initandlisten] connection accepted from 192.168.3.36:61108 #4284138 (115 connections now open)
      Wed Sep 25 06:39:59.168 [conn4284138] end connection 192.168.3.36:61108 (114 connections now open)
      Wed Sep 25 06:39:59.391 [initandlisten] connection accepted from 192.168.3.36:61111 #4284139 (115 connections now open)
      Wed Sep 25 06:39:59.426 [initandlisten] connection accepted from 192.168.3.37:55996 #4284140 (116 connections now open)
      Wed Sep 25 06:39:59.435 [conn4284140] end connection 192.168.3.37:55996 (115 connections now open)
      Wed Sep 25 06:39:59.440 [conn4284139] end connection 192.168.3.36:61111 (114 connections now open)
      Wed Sep 25 06:39:59.620 [initandlisten] connection accepted from 192.168.3.34:64395 #4284141 (115 connections now open)
      Wed Sep 25 06:39:59.762 [conn4284141] end connection 192.168.3.34:64395 (114 connections now open)

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              rassi J Rassi
              Reporter:
              matthewcanty Matthew Canty
              Participants:
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: