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

do not dump stack on stepdown during cleanupOrphaned

    • Type: Icon: Improvement Improvement
    • Resolution: Done
    • Priority: Icon: Minor - P4 Minor - P4
    • 3.3.4
    • Affects Version/s: None
    • Component/s: Sharding
    • Fully Compatible
    • Sharding 10 (02/19/16), Sharding 12 (04/01/16)

      Non-fatal stacktraces should be avoided in logfiles (unless traceExceptions is on), since they can cause user confusion by falsely conveying a heightened sense of importance.

      Affects 2.6, 3.0 and 3.1.

      2015-08-31T17:57:00.547+1000 I SHARDING [conn127] remotely refreshing metadata for test.test based on current shard version 2|0||55e3f24ec97f895066a73485, current metadata version is 2|1||55e3f24ec97f895066a73485
      2015-08-31T17:57:00.548+1000 I SHARDING [conn127] metadata of collection test.test already up to date (shard version : 2|0||55e3f24ec97f895066a73485, took 0ms)
      2015-08-31T17:57:00.548+1000 I SHARDING [conn127] Deleter starting delete for: test.test from { _id: 0.0 } -> { _id: MaxKey }, with opId: 1001673
      2015-08-31T17:57:03.058+1000 I COMMAND  [conn163] Attempting to step down in response to replSetStepDown command
      2015-08-31T17:57:03.062+1000 I -        [conn127] Assertion: 11601:operation was interrupted
      2015-08-31T17:57:03.079+1000 I CONTROL  [conn127]
       0xf5e669 0xf074d1 0xeeb7df 0xeeb88c 0x9d010f 0xbed523 0xbea44a 0x92a191 0x92b131 0x9bdc64 0x9bebed 0x9bf8fb 0xb9340a 0xaa3480 0x7e99fd 0xf1badb 0x7fb04b438182 0x7fb04a538efd
      ----- BEGIN BACKTRACE -----
      {"backtrace":[{"b":"400000","o":"B5E669"},{"b":"400000","o":"B074D1"},{"b":"400000","o":"AEB7DF"},{"b":"400000","o":"AEB88C"},{"b":"400000","o":"5D010F"},{"b":"400000","o":"7ED523"},{"b":"400000","o":"7EA44A"},{"b":"400000","o":"52A191"},{"b":"400000","o":"52B131"},{"b":"400000","o":"5BDC64"},{"b":"400000","o":"5BEBED"},{"b":"400000","o":"5BF8FB"},{"b":"400000","o":"79340A"},{"b":"400000","o":"6A3480"},{"b":"400000","o":"3E99FD"},{"b":"400000","o":"B1BADB"},{"b":"7FB04B430000","o":"8182"},{"b":"7FB04A43E000","o":"FAEFD"}],"processInfo":{ "mongodbVersion" : "3.0.6", "gitVersion" : "1ef45a23a4c5e3480ac919b28afcba3c615488f2", "uname" : { "sysname" : "Linux", "release" : "3.13.0-39-generic", "version" : "#66-Ubuntu SMP Tue Oct 28 13:30:27 UTC 2014", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000" }, { "b" : "7FFF95C4F000", "elfType" : 3 }, { "b" : "7FB04B430000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3 }, { "b" : "7FB04B228000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3 }, { "b" : "7FB04B024000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3 }, { "b" : "7FB04AD20000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3 }, { "b" : "7FB04AA1A000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3 }, { "b" : "7FB04A804000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3 }, { "b" : "7FB04A43E000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3 }, { "b" : "7FB04B64E000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3 } ] }}
       mongod(_ZN5mongo15printStackTraceERSo+0x29) [0xf5e669]
       mongod(_ZN5mongo10logContextEPKc+0xE1) [0xf074d1]
       mongod(_ZN5mongo11msgassertedEiPKc+0xAF) [0xeeb7df]
       mongod(+0xAEB88C) [0xeeb88c]
       mongod(_ZN5mongo7Helpers11removeRangeEPNS_16OperationContextERKNS_8KeyRangeEbRKNS_19WriteConcernOptionsEPNS0_11RemoveSaverEbb+0x11EF) [0x9d010f]
       mongod(_ZN5mongo17RangeDeleterDBEnv11deleteRangeEPNS_16OperationContextERKNS_16RangeDeleteEntryEPxPSs+0x393) [0xbed523]
       mongod(_ZN5mongo12RangeDeleter9deleteNowEPNS_16OperationContextERKNS_19RangeDeleterOptionsEPSs+0x42A) [0xbea44a]
       mongod(_ZN5mongo19cleanupOrphanedDataEPNS_16OperationContextERKNS_15NamespaceStringERKNS_7BSONObjERKNS_19WriteConcernOptionsEPS5_PSs+0x481) [0x92a191]
       mongod(_ZN5mongo22CleanupOrphanedCommand3runEPNS_16OperationContextERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb+0x731) [0x92b131]
       mongod(_ZN5mongo12_execCommandEPNS_16OperationContextEPNS_7CommandERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb+0x34) [0x9bdc64]
       mongod(_ZN5mongo7Command11execCommandEPNS_16OperationContextEPS0_iPKcRNS_7BSONObjERNS_14BSONObjBuilderEb+0xC1D) [0x9bebed]
       mongod(_ZN5mongo12_runCommandsEPNS_16OperationContextEPKcRNS_7BSONObjERNS_11_BufBuilderINS_16TrivialAllocatorEEERNS_14BSONObjBuilderEbi+0x28B) [0x9bf8fb]
       mongod(_ZN5mongo8runQueryEPNS_16OperationContextERNS_7MessageERNS_12QueryMessageERKNS_15NamespaceStringERNS_5CurOpES3_+0x77A) [0xb9340a]
       mongod(_ZN5mongo16assembleResponseEPNS_16OperationContextERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0xB10) [0xaa3480]
       mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0xDD) [0x7e99fd]
       mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x34B) [0xf1badb]
       libpthread.so.0(+0x8182) [0x7fb04b438182]
       libc.so.6(clone+0x6D) [0x7fb04a538efd]
      -----  END BACKTRACE  -----
      2015-08-31T17:57:03.081+1000 W COMMAND  [conn127] Error encountered while deleting range: nstest.test from { _id: 0.0 } -> { _id: MaxKey }, cause by: :: caused by :: 11601 operation was interrupted
      2015-08-31T17:57:03.082+1000 I COMMAND  [conn127] command admin.$cmd command: cleanupOrphaned { cleanupOrphaned: "test.test", startingFromKey: { _id: MinKey } } keyUpdates:0 writeConflicts:0 numYields:0 reslen:257 locks:{ Global: { acquireCount: { r: 2071, w: 2067 } }, MMAPV1Journal: { acquireCount: { r: 2, w: 2067 }, acquireWaitCount: { w: 5 }, timeAcquiringMicros: { w: 4631 } }, Database: { acquireCount: { r: 2, w: 2067 } }, Collection: { acquireCount: { R: 2, W: 1034 } }, oplog: { acquireCount: { w: 1033 } } } 2534ms
      2015-08-31T17:57:03.337+1000 I REPL     [ReplicationExecutor] transition to SECONDARY
      2015-08-31T17:57:03.337+1000 I NETWORK  [conn9] end connection 127.0.0.1:50710 (10 connections now open)
      2015-08-31T17:57:03.337+1000 I NETWORK  [conn8] end connection 127.0.0.1:50702 (9 connections now open)
      2015-08-31T17:57:03.337+1000 I NETWORK  [conn18] end connection 127.0.0.1:50783 (8 connections now open)
      2015-08-31T17:57:03.338+1000 I NETWORK  [conn127] end connection 127.0.0.1:53778 (7 connections now open)
      2015-08-31T17:57:03.338+1000 I NETWORK  [conn17] end connection 127.0.0.1:50782 (6 connections now open)
      2015-08-31T17:57:03.338+1000 I NETWORK  [conn21] end connection 127.0.0.1:50790 (5 connections now open)
      2015-08-31T17:57:03.338+1000 I COMMAND  [conn163] command admin.$cmd command: replSetStepDown { replSetStepDown: 60.0 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:37 locks:{ Global: { acquireCount: { R: 1 } } } 280ms
      2015-08-31T17:57:03.338+1000 I NETWORK  [conn20] end connection 127.0.0.1:50789 (4 connections now open)
      2015-08-31T17:57:03.341+1000 I NETWORK  [conn163] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [127.0.0.1:54264]
      2015-08-31T17:57:03.346+1000 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:57932 #412 (4 connections now open)
      2015-08-31T17:57:05.617+1000 I REPL     [ReplicationExecutor] replSetElect voting yea for genique:11116 (1)
      2015-08-31T17:57:07.339+1000 I REPL     [ReplicationExecutor] Member genique:11116 is now in state PRIMARY
      2015-08-31T17:57:08.071+1000 I NETWORK  [conn19] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [127.0.0.1:50788]
      

            Assignee:
            dianna.hohensee@mongodb.com Dianna Hohensee (Inactive)
            Reporter:
            kevin.pulo@mongodb.com Kevin Pulo
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: